invoice events problem

nsi...@gmail.com

unread,

Oct 31, 2013, 8:07:40 AM10/31/13

to killbill...@googlegroups.com

Hi Piere
I was testing the subscription flow and I am bit confused with the invoice events.
Running multiple times the same request flow i found invoice event are not getting processed every time. I am using kill-bill 1.6.17 version.

regards,
Nitin

1 > POST http://127.0.0.1:8080/1.0/kb/accounts
1 > host: 127.0.0.1:8080
1 > content-type: application/json; charset=utf-8
1 > x-killbill-createdby: ccb
1 > x-killbill-reason: userrequest
1 > x-killbill-comment: client impletentation
1 > x-killbill-apikey: bob
1 > x-killbill-apisecret: lazar
1 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
1 > connection: keep-alive
1 > accept: */*
1 > user-agent: NING/1.0
1 > content-length: 505
1 >

12:50:23.444 [http-bio-8080-exec-5] INFO c.s.j.a.c.filter.LoggingFilter - 1 * Server out-bound response
1 < 201
1 < Location: http://127.0.0.1:8080/1.0/kb/accounts/82126928-1441-4e1b-8ea6-1c6ef06a828c
1 < Content-Type: application/json
1 <

12:50:23.804 [http-bio-8080-exec-9] INFO c.s.j.a.c.filter.LoggingFilter - 2 * Server in-bound request
2 > GET http://127.0.0.1:8080/1.0/kb/accounts?externalKey=59f7afbf-254e-4ea8-a29d-c300eb2e991f
2 > host: 127.0.0.1:8080
2 > content-type: application/json; charset=utf-8
2 > x-killbill-createdby:
2 > x-killbill-reason:
2 > x-killbill-comment:
2 > x-killbill-apikey: bob
2 > x-killbill-apisecret: lazar
2 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
2 > connection: keep-alive
2 > accept: */*
2 > user-agent: NING/1.0
2 >

12:50:23.830 [http-bio-8080-exec-9] INFO c.s.j.a.c.filter.LoggingFilter - 2 * Server out-bound response
2 < 200
2 < Content-Type: application/json
2 <

12:50:24.299 [http-bio-8080-exec-3] INFO c.s.j.a.c.filter.LoggingFilter - 3 * Server in-bound request
3 > POST http://127.0.0.1:8080/1.0/kb/accounts/82126928-1441-4e1b-8ea6-1c6ef06a828c/paymentMethods?isDefault=true
3 > host: 127.0.0.1:8080
3 > content-type: application/json; charset=utf-8
3 > x-killbill-createdby: ccb
3 > x-killbill-reason: userrequest
3 > x-killbill-comment: client impletentation
3 > x-killbill-apikey: bob
3 > x-killbill-apisecret: lazar
3 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
3 > connection: keep-alive
3 > accept: */*
3 > user-agent: NING/1.0
3 > content-length: 391
3 >

12:50:24.710 [http-bio-8080-exec-3] INFO c.s.j.a.c.filter.LoggingFilter - 3 * Server out-bound response
3 < 201
3 < Location: http://127.0.0.1:8080/1.0/kb/paymentMethods/8a96f19b-0026-4517-b5b1-145e52263494
3 < Content-Type: application/json
3 <

12:50:25.528 [http-bio-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 4 * Server in-bound request
4 > GET http://127.0.0.1:8080/1.0/kb/accounts?externalKey=59f7afbf-254e-4ea8-a29d-c300eb2e991f
4 > host: 127.0.0.1:8080
4 > content-type: application/json; charset=utf-8
4 > x-killbill-createdby:
4 > x-killbill-reason:
4 > x-killbill-comment:
4 > x-killbill-apikey: bob
4 > x-killbill-apisecret: lazar
4 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
4 > connection: keep-alive
4 > accept: */*
4 > user-agent: NING/1.0
4 >

12:50:25.549 [http-bio-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 4 * Server out-bound response
4 < 200
4 < Content-Type: application/json
4 <

12:50:26.947 [http-bio-8080-exec-5] INFO c.s.j.a.c.filter.LoggingFilter - 5 * Server in-bound request
5 > POST http://127.0.0.1:8080/1.0/kb/subscriptions
5 > host: 127.0.0.1:8080
5 > content-type: application/json; charset=utf-8
5 > x-killbill-createdby: ccb
5 > x-killbill-reason: userrequest
5 > x-killbill-comment: client impletentation
5 > x-killbill-apikey: bob
5 > x-killbill-apisecret: lazar
5 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
5 > connection: keep-alive
5 > accept: */*
5 > user-agent: NING/1.0
5 > content-length: 424
5 >

12:50:27.792 [http-bio-8080-exec-5] INFO c.s.j.a.c.filter.LoggingFilter - 5 * Server out-bound response
5 < 201
5 < Location: http://127.0.0.1:8080/1.0/kb/subscriptions/681b2765-69da-4b25-bdda-acde03674b25
5 < Content-Type: application/json
5 <

12:50:28.094 [http-bio-8080-exec-5] INFO c.s.j.a.c.filter.LoggingFilter - 6 * Server in-bound request
6 > GET http://127.0.0.1:8080/1.0/kb/subscriptions/681b2765-69da-4b25-bdda-acde03674b25
6 > host: 127.0.0.1:8080
6 > content-type: application/json; charset=utf-8
6 > x-killbill-createdby: ccb
6 > x-killbill-reason: userrequest
6 > x-killbill-comment: client impletentation
6 > x-killbill-apikey: bob
6 > x-killbill-apisecret: lazar
6 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
6 > connection: keep-alive
6 > accept: */*
6 > user-agent: NING/1.0
6 >

12:50:28.375 [http-bio-8080-exec-5] INFO c.s.j.a.c.filter.LoggingFilter - 6 * Server out-bound response
6 < 200
6 < Content-Type: application/json
6 <

12:50:29.862 [bus-th] INFO c.n.b.j.p.b.BillCycleDayCalculator - Calculated BCD: subscription id 681b2765-69da-4b25-bdda-acde03674b25, subscription start 2013-10-31T07:20:27.000Z, timezone UTC, bcd UTC 31, bcd local 31
12:50:30.048 [bus-th] INFO c.n.b.j.p.b.DefaultInternalBillingApi - Computed billing events for accountId 82126928-1441-4e1b-8ea6-1c6ef06a828c
Billing Events Raw
DefaultBillingEvent{type=CREATE, effectiveDate=2013-10-31T07:20:27.000Z, planPhaseName=frenzo-usage-monthly-evergreen, subscriptionId=681b2765-69da-4b25-bdda-acde03674b25, totalOrdering=75, accountId=82126928-1441-4e1b-8ea6-1c6ef06a828c}
Billing Events After Blocking
DefaultBillingEvent{type=CREATE, effectiveDate=2013-10-31T07:20:27.000Z, planPhaseName=frenzo-usage-monthly-evergreen, subscriptionId=681b2765-69da-4b25-bdda-acde03674b25, totalOrdering=75, accountId=82126928-1441-4e1b-8ea6-1c6ef06a828c}
12:50:30.109 [bus-th] INFO c.n.b.i.g.DefaultInvoiceGenerator - Invoice items generated for invoiceId 6edb7ca3-81c0-4f5e-9b51-8135cac07237 and accountId 82126928-1441-4e1b-8ea6-1c6ef06a828c
DefaultBillingEvent{type=CREATE, effectiveDate=2013-10-31T07:20:27.000Z, planPhaseName=frenzo-usage-monthly-evergreen, subscriptionId=681b2765-69da-4b25-bdda-acde03674b25, totalOrdering=75, accountId=82126928-1441-4e1b-8ea6-1c6ef06a828c}
RECURRING{startDate=2013-10-31, endDate=2013-11-30, amount=5.00, rate=5, subscriptionId=681b2765-69da-4b25-bdda-acde03674b25, linkedItemId=null}
12:50:30.109 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - Generated invoice 6edb7ca3-81c0-4f5e-9b51-8135cac07237 with 1 items for accountId 82126928-1441-4e1b-8ea6-1c6ef06a828c and targetDate 2013-10-31 (targetDateTime 2013-10-31T07:20:27.000Z)
12:50:30.378 [bus-th] INFO c.n.b.i.n.DefaultNextBillingDatePoster - Queuing next billing date notification at 2013-11-30T07:20:27.000Z for subscriptionId 681b2765-69da-4b25-bdda-acde03674b25
12:50:33.204 [bus-th] INFO c.n.b.payment.bus.InvoiceHandler - Received invoice creation notification for account 82126928-1441-4e1b-8ea6-1c6ef06a828c and invoice 6edb7ca3-81c0-4f5e-9b51-8135cac07237
DO PAYMENT OF 82126928-1441-4e1b-8ea6-1c6ef06a828c::de6cffc3-d073-475e-8b3c-917331358a8e::5.00
12:51:02.284 [http-bio-8080-exec-4] INFO c.s.j.a.c.filter.LoggingFilter - 7 * Server in-bound request
7 > POST http://127.0.0.1:8080/1.0/kb/accounts
7 > host: 127.0.0.1:8080
7 > content-type: application/json; charset=utf-8
7 > x-killbill-createdby: ccb
7 > x-killbill-reason: userrequest
7 > x-killbill-comment: client impletentation
7 > x-killbill-apikey: bob
7 > x-killbill-apisecret: lazar
7 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
7 > connection: keep-alive
7 > accept: */*
7 > user-agent: NING/1.0
7 > content-length: 505
7 >

12:51:02.435 [http-bio-8080-exec-4] INFO c.s.j.a.c.filter.LoggingFilter - 7 * Server out-bound response
7 < 201
7 < Location: http://127.0.0.1:8080/1.0/kb/accounts/9db4dbaa-378d-4cc7-b5d9-f6fa297fea8a
7 < Content-Type: application/json
7 <

12:51:02.730 [http-bio-8080-exec-1] INFO c.s.j.a.c.filter.LoggingFilter - 8 * Server in-bound request
8 > GET http://127.0.0.1:8080/1.0/kb/accounts?externalKey=8375fc5a-a4de-42a0-a3ab-f854c96da51c
8 > host: 127.0.0.1:8080
8 > content-type: application/json; charset=utf-8
8 > x-killbill-createdby:
8 > x-killbill-reason:
8 > x-killbill-comment:
8 > x-killbill-apikey: bob
8 > x-killbill-apisecret: lazar
8 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
8 > connection: keep-alive
8 > accept: */*
8 > user-agent: NING/1.0
8 >

12:51:02.757 [http-bio-8080-exec-1] INFO c.s.j.a.c.filter.LoggingFilter - 8 * Server out-bound response
8 < 200
8 < Content-Type: application/json
8 <

12:51:03.151 [http-bio-8080-exec-11] INFO c.s.j.a.c.filter.LoggingFilter - 9 * Server in-bound request
9 > POST http://127.0.0.1:8080/1.0/kb/accounts/9db4dbaa-378d-4cc7-b5d9-f6fa297fea8a/paymentMethods?isDefault=true
9 > host: 127.0.0.1:8080
9 > content-type: application/json; charset=utf-8
9 > x-killbill-createdby: ccb
9 > x-killbill-reason: userrequest
9 > x-killbill-comment: client impletentation
9 > x-killbill-apikey: bob
9 > x-killbill-apisecret: lazar
9 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
9 > connection: keep-alive
9 > accept: */*
9 > user-agent: NING/1.0
9 > content-length: 391
9 >

12:51:03.468 [http-bio-8080-exec-11] INFO c.s.j.a.c.filter.LoggingFilter - 9 * Server out-bound response
9 < 201
9 < Location: http://127.0.0.1:8080/1.0/kb/paymentMethods/335601c4-ed8e-42bc-ba11-472c2cec86b8
9 < Content-Type: application/json
9 <

12:51:03.749 [http-bio-8080-exec-5] INFO c.s.j.a.c.filter.LoggingFilter - 10 * Server in-bound request
10 > GET http://127.0.0.1:8080/1.0/kb/accounts?externalKey=8375fc5a-a4de-42a0-a3ab-f854c96da51c
10 > host: 127.0.0.1:8080
10 > content-type: application/json; charset=utf-8
10 > x-killbill-createdby:
10 > x-killbill-reason:
10 > x-killbill-comment:
10 > x-killbill-apikey: bob
10 > x-killbill-apisecret: lazar
10 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
10 > connection: keep-alive
10 > accept: */*
10 > user-agent: NING/1.0
10 >

12:51:03.766 [http-bio-8080-exec-5] INFO c.s.j.a.c.filter.LoggingFilter - 10 * Server out-bound response
10 < 200
10 < Content-Type: application/json
10 <

12:51:05.146 [http-bio-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 11 * Server in-bound request
11 > POST http://127.0.0.1:8080/1.0/kb/subscriptions
11 > host: 127.0.0.1:8080
11 > content-type: application/json; charset=utf-8
11 > x-killbill-createdby: ccb
11 > x-killbill-reason: userrequest
11 > x-killbill-comment: client impletentation
11 > x-killbill-apikey: bob
11 > x-killbill-apisecret: lazar
11 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
11 > connection: keep-alive
11 > accept: */*
11 > user-agent: NING/1.0
11 > content-length: 424
11 >

12:51:05.519 [http-bio-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 11 * Server out-bound response
11 < 201
11 < Location: http://127.0.0.1:8080/1.0/kb/subscriptions/6e760b12-60fa-4810-9022-742b5e6792ce
11 < Content-Type: application/json
11 <

12:51:05.812 [http-bio-8080-exec-3] INFO c.s.j.a.c.filter.LoggingFilter - 12 * Server in-bound request
12 > GET http://127.0.0.1:8080/1.0/kb/subscriptions/6e760b12-60fa-4810-9022-742b5e6792ce
12 > host: 127.0.0.1:8080
12 > content-type: application/json; charset=utf-8
12 > x-killbill-createdby: ccb
12 > x-killbill-reason: userrequest
12 > x-killbill-comment: client impletentation
12 > x-killbill-apikey: bob
12 > x-killbill-apisecret: lazar
12 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
12 > connection: keep-alive
12 > accept: */*
12 > user-agent: NING/1.0
12 >

12:51:06.001 [http-bio-8080-exec-3] INFO c.s.j.a.c.filter.LoggingFilter - 12 * Server out-bound response
12 < 200
12 < Content-Type: application/json
12 <

Pierre-Alexandre Meyer

unread,

Oct 31, 2013, 8:15:22 AM10/31/13

to Nitin Singh, killbill...@googlegroups.com

On Thu, Oct 31, 2013 at 8:07 AM, <nsi...@gmail.com> wrote:

I was testing the subscription flow and I am bit confused with the invoice events.
Running multiple times the same request flow i found invoice event are not getting processed every time. I am using kill-bill 1.6.17 version.

It's a bit hard to debug without having access to the content of the POST requests.

Could you share either the curl commands you are using, the code (maybe you are using one of our client libraries?) and/or the content of the subscription_events table?

Are you also using a custom catalog? How did you define your frenzo-usage-monthly-evergreen phase?

--

Pierre

nsi...@gmail.com

unread,

Nov 5, 2013, 11:31:15 PM11/5/13

to killbill...@googlegroups.com, Nitin Singh

mysql> SELECT * FROM subscription_events s where requested_date > '2013-10-31';
+-----------+--------------------------------------+------------+-----------+---------------------+---------------------+--------------------------------------+----------------------+--------------------------------+-----------------+-----------------+-----------+------------+---------------------+------------+---------------------+-------------------+------------------+
| record_id | id | event_type | user_type | requested_date | effective_date | subscription_id | plan_name | phase_name | price_list_name | current_version | is_active | created_by | created_date | updated_by | updated_date | account_record_id | tenant_record_id |
+-----------+--------------------------------------+------------+-----------+---------------------+---------------------+--------------------------------------+----------------------+--------------------------------+-----------------+-----------------+-----------+------------+---------------------+------------+---------------------+-------------------+------------------+
| 74 | 31a93697-5e42-4b6e-a8e9-22ebb355a336 | API_USER | CREATE | 2013-10-31 12:21:42 | 2013-10-31 12:21:42 | f0f7e677-7283-4e78-b459-511cb139022a | frenzo-usage-monthly | frenzo-usage-monthly-evergreen | DEFAULT | 1 | 1 | ccb | 2013-10-31 12:21:42 | ccb | 2013-10-31 12:21:42 | 66 | 1 |
| 75 | c7536596-b149-4fa2-9ea4-a688ff358fa0 | API_USER | CREATE | 2013-10-31 12:50:27 | 2013-10-31 12:50:27 | 681b2765-69da-4b25-bdda-acde03674b25 | frenzo-usage-monthly | frenzo-usage-monthly-evergreen | DEFAULT | 1 | 1 | ccb | 2013-10-31 12:50:27 | ccb | 2013-10-31 12:50:27 | 67 | 1 |
| 76 | 2a742d70-9959-4f06-b34c-7e3b1d526ea9 | API_USER | CREATE | 2013-10-31 12:51:05 | 2013-10-31 12:51:05 | 6e760b12-60fa-4810-9022-742b5e6792ce | frenzo-usage-monthly | frenzo-usage-monthly-evergreen | DEFAULT | 1 | 1 | ccb | 2013-10-31 12:51:05 | ccb | 2013-10-31 12:51:05 | 68 | 1 |
+-----------+--------------------------------------+------------+-----------+---------------------+---------------------+--------------------------------------+----------------------+--------------------------------+-----------------+-----------------+-----------+------------+---------------------+------------+---------------------+-------------------+------------------+
3 rows in set (0.00 sec)

nsi...@gmail.com

unread,

Nov 5, 2013, 11:33:05 PM11/5/13

to killbill...@googlegroups.com, Nitin Singh

<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<catalog xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:noNamespaceSchemaLocation="CatalogSchema.xsd ">

<effectiveDate>2013-10-01T00:00:00+00:00</effectiveDate>
<catalogName>aclcatalog</catalogName>

<products>
<product name="frenzo-usage">
<category>BASE</category>
<included>
<addonProduct>gift</addonProduct>
</included>
<available>
<addonProduct>extra-gift</addonProduct>
</available>
</product>
<product name="frenzo-mini">
<category>BASE</category>
<limits>
<limit>
<unit>shells</unit>
<max>5</max>
</limit>
</limits>
</product>
<product name="gift">
<category>ADD_ON</category>
</product>
<product name="extra-gift">
<category>ADD_ON</category>
</product>
</products>

<rules>
<changePolicy>
<changePolicyCase>
<fromBillingPeriod>MONTHLY</fromBillingPeriod>
<toProduct>frenzo-mini</toProduct>
<toBillingPeriod>MONTHLY</toBillingPeriod>
<policy>END_OF_TERM</policy>
</changePolicyCase>
<changePolicyCase>
<phaseType>EVERGREEN</phaseType>
<policy>IMMEDIATE</policy>
</changePolicyCase>
</changePolicy>
<changeAlignment>
<changeAlignmentCase>
<alignment>START_OF_SUBSCRIPTION</alignment>
</changeAlignmentCase>
</changeAlignment>
<createAlignment>
<createAlignmentCase>
<product>gift</product>
<alignment>START_OF_SUBSCRIPTION</alignment>
</createAlignmentCase>
<createAlignmentCase>
<alignment>START_OF_SUBSCRIPTION</alignment>
</createAlignmentCase>
</createAlignment>
<billingAlignment>
<billingAlignmentCase>
<alignment>ACCOUNT</alignment>
</billingAlignmentCase>
</billingAlignment>
<priceList>
<priceListCase>
<toPriceList>DEFAULT</toPriceList>
</priceListCase>
</priceList>
</rules>

<plans>
<plan name="frenzo-usage-monthly">
<product>frenzo-usage</product>

<finalPhase type="EVERGREEN">
<duration>
<unit>UNLIMITED</unit>
</duration>
<billingPeriod>MONTHLY</billingPeriod>
<recurringPrice>
<price><currency>GBP</currency><value>29.95</value></price>
<price><currency>INR</currency><value>5</value></price>
<price><currency>USD</currency><value>29.95</value></price>
</recurringPrice>

</finalPhase>
</plan>
<plan name="frenzo-mini-monthly">
<product>frenzo-mini</product>

<finalPhase type="EVERGREEN">
<duration>
<unit>UNLIMITED</unit>
<number>-1</number>
</duration>
<billingPeriod>MONTHLY</billingPeriod>
<recurringPrice>
<price><currency>USD</currency><value>249.95</value></price>
<price><currency>INR</currency><value>1</value></price>
<price><currency>GBP</currency><value>169.95</value></price>
</recurringPrice>
</finalPhase>
</plan>
<plan name="gift-monthly">
<product>gift</product>
<finalPhase type="EVERGREEN">
<duration>
<unit>UNLIMITED</unit>
</duration>
<billingPeriod>MONTHLY</billingPeriod>
<recurringPrice>
<price><currency>USD</currency><value>1999.95</value></price>
<price><currency>INR</currency><value>2</value></price>
<price><currency>GBP</currency><value>1999.95</value></price>
</recurringPrice>
</finalPhase>
</plan>
<plan name="extra-gift-monthly">
<product>extra-gift</product>
<finalPhase type="EVERGREEN">
<duration>
<unit>UNLIMITED</unit>
</duration>
<billingPeriod>MONTHLY</billingPeriod>
<recurringPrice>
<price><currency>USD</currency><value>1999.95</value></price>
<price><currency>INR</currency><value>5</value></price>
<price><currency>GBP</currency><value>1999.95</value></price>
</recurringPrice>
</finalPhase>
</plan>
</plans>
<priceLists>
<defaultPriceList name="DEFAULT">
<plans>
<plan>frenzo-usage-monthly</plan>
<plan>frenzo-mini-monthly</plan>
</plans>
</defaultPriceList>
</priceLists>
</catalog>

nsi...@gmail.com

unread,

Nov 5, 2013, 11:38:29 PM11/5/13

to killbill...@googlegroups.com, Nitin Singh

I am using your killbill-client api but modified it as it was based on old api version I guess. I am testing with following test

@Test(groups = "slow")
public void testCreateAndsubscribe() throws Exception {
final KillBillAccount account = new KillBillAccount();
account.setName(UUID.randomUUID().toString());
account.setExternalKey(UUID.randomUUID().toString());
account.setEmail(UUID.randomUUID().toString());
account.setCurrency("INR");
final KillBillAccount retrievedAccount = account.createAccount();
final AccountJson retrievedAccountJson = retrievedAccount.doCreateAccountWithDefaultPaymentMethod(retrievedAccount.toAccountJson());
Assert.assertNotNull(retrievedAccountJson.getPaymentMethodId());
Thread.sleep(1000);
retrievedAccount.setPaymentMethodId(retrievedAccountJson.getPaymentMethodId());
KillBillSubscription killBillSubscription = new KillBillSubscription();
SubscriptionJson json=killBillSubscription.createSubscription(null, "frenzo-usage", "BASE", "MONTHLY", false,retrievedAccount.getAccountId(),UUID.randomUUID().toString(),PriceListSet.DEFAULT_PRICELIST_NAME);
Assert.assertEquals(json.getAccountId(),retrievedAccount.getAccountId());
System.out.println(json.getAccountId()+"::"+json.getSubscriptionId());

}

I have also noticed this invoice event not triggering when I tested with the curl request in the doc and posted my first query in this group. I mentioned the trying again with different plan triggered the invoice.

regards,
Nitin

Stephane Brossier

unread,

Nov 5, 2013, 11:44:39 PM11/5/13

to nsi...@gmail.com, killbill...@googlegroups.com

Hi Nitin,

On Nov 5, 2013, at 8:38 PM, nsi...@gmail.com wrote:

> I am using your killbill-client api but modified it as it was based on old api version I guess.

Yes indeed. we are aware that the java client api is not up to date. Please submit pull requests for any fix that you have.

> I am testing with following test
>
> @Test(groups = "slow")
> public void testCreateAndsubscribe() throws Exception {
> final KillBillAccount account = new KillBillAccount();
> account.setName(UUID.randomUUID().toString());
> account.setExternalKey(UUID.randomUUID().toString());
> account.setEmail(UUID.randomUUID().toString());
> account.setCurrency("INR");
> final KillBillAccount retrievedAccount = account.createAccount();
> final AccountJson retrievedAccountJson = retrievedAccount.doCreateAccountWithDefaultPaymentMethod(retrievedAccount.toAccountJson());
> Assert.assertNotNull(retrievedAccountJson.getPaymentMethodId());
> Thread.sleep(1000);
> retrievedAccount.setPaymentMethodId(retrievedAccountJson.getPaymentMethodId());
> KillBillSubscription killBillSubscription = new KillBillSubscription();
> SubscriptionJson json=killBillSubscription.createSubscription(null, "frenzo-usage", "BASE", "MONTHLY", false,retrievedAccount.getAccountId(),UUID.randomUUID().toString(),PriceListSet.DEFAULT_PRICELIST_NAME);
> Assert.assertEquals(json.getAccountId(),retrievedAccount.getAccountId());
> System.out.println(json.getAccountId()+"::"+json.getSubscriptionId());
>
> }

From looking at the data in subscription_events table it looks like you ran that test 3 times. Since you commented the TRAIl phase in your catalog, it is expected to ONLy see create events for each iteration of your tests. So based on test and data i have seen, i am not seeing any issues.

Could you clarify the problem with the invoices?

Maybe a query in invoice and invoice_items tables to give us a clue what you see there?

>
>
> I have also noticed this invoice event not triggering when I tested with the curl request in the doc and posted my first query in this group.
> I mentioned the trying again with different plan triggered the invoice.

Please provide us with details on which one fails and which one succeeds.

Thanks,

S.

>
> regards,
> Nitin
>
> --
> 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 http://groups.google.com/group/killbilling-users.
> To view this discussion on the web visit https://groups.google.com/d/msgid/killbilling-users/4af3db73-8877-4acc-9f85-568b3124836e%40googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.

nsi...@gmail.com

unread,

Nov 6, 2013, 1:10:53 AM11/6/13

to killbill...@googlegroups.com, nsi...@gmail.com

Hi Stiphane

I am upgrading my kill bill code from 0.6.7 to 0.8.1. After that I'll rerun the code and will post my findings.
The issue I have posted was some times invoice dispatcher is generating invoice and some times not. I just watching the logs which I have posted. Today I have found that invoice dispatcher is generating invoice but invoice handler is not called each time to initiate payment. I'll investigate more today with the new code base and will post my findings.

One more thing I want to understand if my approach is correct for the billing system. I want to trigger payment for any subscription and if payment is successful mark them subscribed. I have tested the billing event by the changing the billing date and it works. I am not sure about the payment status and subscription given at the time of creation. Can I make subscription creation and payment synchronously or on the basis of payment create subscription.

Regards,
Nitin

nsi...@gmail.com

unread,

Nov 6, 2013, 7:55:32 AM11/6/13

to killbill...@googlegroups.com, nsi...@gmail.com

I have tested with 0.8.1
same scenario test case subscription table has data

mysql> SELECT * FROM subscriptions s
-> ;
+-----------+--------------------------------------+--------------------------------------+----------+---------------------+---------------------+----------------+----------------------+-------------------+------------+---------------------+------------+---------------------+-------------------+------------------+
| record_id | id | bundle_id | category | start_date | bundle_start_date | active_version | charged_through_date | paid_through_date | created_by | created_date | updated_by | updated_date | account_record_id | tenant_record_id |
+-----------+--------------------------------------+--------------------------------------+----------+---------------------+---------------------+----------------+----------------------+-------------------+------------+---------------------+------------+---------------------+-------------------+------------------+
| 1 | 0b7ab9ac-a397-480e-8ff2-4035b17ef421 | 36daaf99-badc-472e-ad83-9f1302fa1f8e | BASE | 2013-11-06 17:19:51 | 2013-11-06 17:19:51 | 1 | NULL | NULL | ccb | 2013-11-06 17:19:50 | ccb | 2013-11-06 17:19:50 | 1 | 1 |
| 2 | 815f0950-610a-4b93-9b8a-62a489b2c34c | dce03ee9-ee63-449d-b67a-0822933ef543 | BASE | 2013-11-06 18:18:05 | 2013-11-06 18:18:05 | 1 | NULL | NULL | ccb | 2013-11-06 18:18:05 | ccb | 2013-11-06 18:18:05 | 2 | 1 |
+-----------+--------------------------------------+--------------------------------------+----------+---------------------+---------------------+----------------+----------------------+-------------------+------------+---------------------+------------+---------------------+-------------------+------------------+
2 rows in set (0.01 sec)

invoice, invoice_item,bus_event and notification is empty

mysql> SELECT * FROM bus_events_history b;
+-----------+--------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------+---------------------+---------------------------------+---------------------------------+---------------------------+------------------+-------------+-------------+
| record_id | class_name | event_json | user_token | created_date | creating_owner | processing_owner | processing_available_date | processing_state | search_key1 | search_key2 |
+-----------+--------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------+---------------------+---------------------------------+---------------------------------+---------------------------+------------------+-------------+-------------+
| 1 | com.ning.billing.account.api.user.DefaultAccountCreationEvent | {"data":{"externalKey":"bf336939-e229-4546-ba0f-7295c6f6640f","name":"e34d2385-493c-4001-9866-608e810de511","firstNameLength":36,"email":"58ef689f-e85b-4a60-b8ae-bcd0cada4e7f","billCycleDayLocal":0,"currency":"INR","paymentMethodId":null,"timeZone":null,"locale":null,"address1":null,"address2":null,"companyName":null,"city":null,"stateOrProvince":null,"postalCode":null,"country":null,"phone":null,"isMigrated":false,"isNotifiedForInvoices":true},"id":"bdcca2c3-1a3f-4299-8113-87514fa563fa","searchKey1":null,"searchKey2":1,"userToken":"f79eb053-bee6-487f-be4e-4d1b3f48f73b"} | f79eb053-bee6-487f-be4e-4d1b3f48f73b | 2013-11-06 17:19:47 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-06 17:19:48 | PROCESSED | NULL | 1 |
| 2 | com.ning.billing.account.api.user.DefaultAccountChangeEvent | {"accountId":"bdcca2c3-1a3f-4299-8113-87514fa563fa","searchKey1":1,"searchKey2":1,"userToken":"5e52194f-6d2f-459e-a3ea-edec5445a657","changedFields":[{"fieldName":"paymentMethodId","oldValue":null,"newValue":"941a86fb-4c85-4f6c-8ae2-edcd20c9b32c","changeDate":"2013-11-06T17:19:48.997+05:30"}]} | 5e52194f-6d2f-459e-a3ea-edec5445a657 | 2013-11-06 17:19:49 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-06 17:19:49 | PROCESSED | 1 | 1 |
| 3 | com.ning.billing.beatrix.extbus.DefaultBusExternalEvent | {"objectId":"bdcca2c3-1a3f-4299-8113-87514fa563fa","objectType":"ACCOUNT","eventType":"ACCOUNT_CHANGE","accountId":"bdcca2c3-1a3f-4299-8113-87514fa563fa","tenantId":"d2c06716-8d4d-41eb-889f-66344046bb80"} | 5e52194f-6d2f-459e-a3ea-edec5445a657 | 2013-11-06 17:19:49 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-06 17:19:49 | PROCESSED | 1 | 1 |
| 4 | com.ning.billing.subscription.api.user.DefaultEffectiveSubscriptionEvent | {"eventId":"1dc30853-0eaf-4b9e-afe8-c6375fc2b037","subscriptionId":"0b7ab9ac-a397-480e-8ff2-4035b17ef421","bundleId":"36daaf99-badc-472e-ad83-9f1302fa1f8e","requestedTransitionTime":"2013-11-06T11:49:51.000Z","effectiveTransitionTime":"2013-11-06T11:49:51.000Z","previousState":null,"previousPlan":null,"previousPhase":null,"previousPriceList":null,"nextState":"ACTIVE","nextPlan":"frenzo-usage-monthly","nextPhase":"frenzo-usage-monthly-evergreen","nextPriceList":"DEFAULT","totalOrdering":0,"transitionType":"CREATE","remainingEventsForUserOperation":0,"startDate":"2013-11-06T11:49:51.000Z","searchKey1":1,"searchKey2":1,"userToken":"78c356b9-5515-42b9-9445-457d4fb0926b"} | 78c356b9-5515-42b9-9445-457d4fb0926b | 2013-11-06 17:19:51 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-06 17:19:51 | PROCESSED | 1 | 1 |
| 5 | com.ning.billing.subscription.api.user.DefaultRequestedSubscriptionEvent | {"eventId":"1dc30853-0eaf-4b9e-afe8-c6375fc2b037","subscriptionId":"0b7ab9ac-a397-480e-8ff2-4035b17ef421","bundleId":"36daaf99-badc-472e-ad83-9f1302fa1f8e","requestedTransitionTime":"2013-11-06T11:49:51.000Z","effectiveTransitionTime":"2013-11-06T11:49:51.000Z","previousState":null,"previousPlan":null,"previousPhase":null,"previousPriceList":null,"nextState":null,"nextPlan":null,"nextPhase":null,"nextPriceList":null,"totalOrdering":0,"transitionType":null,"remainingEventsForUserOperation":0,"startDate":null,"searchKey1":1,"searchKey2":1,"userToken":"78c356b9-5515-42b9-9445-457d4fb0926b"} | 78c356b9-5515-42b9-9445-457d4fb0926b | 2013-11-06 17:19:51 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-06 17:19:52 | PROCESSED | 1 | 1 |
| 6 | com.ning.billing.account.api.user.DefaultAccountCreationEvent | {"data":{"externalKey":"7521537b-c0be-4477-ab04-499be79a9219","name":"2c084c68-bd60-485c-8c03-6ec06f758650","firstNameLength":36,"email":"c3209b22-b27b-42b8-92ba-563b5d89fd1f","billCycleDayLocal":0,"currency":"INR","paymentMethodId":null,"timeZone":null,"locale":null,"address1":null,"address2":null,"companyName":null,"city":null,"stateOrProvince":null,"postalCode":null,"country":null,"phone":null,"isMigrated":false,"isNotifiedForInvoices":true},"id":"8eecc225-8799-4cc3-9111-482da0671ee9","searchKey1":null,"searchKey2":1,"userToken":"abdf3929-3f55-4a6f-a3da-ea18fb00d160"} | abdf3929-3f55-4a6f-a3da-ea18fb00d160 | 2013-11-06 18:18:02 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-06 18:18:02 | PROCESSED | NULL | 1 |
| 7 | com.ning.billing.account.api.user.DefaultAccountChangeEvent | {"accountId":"8eecc225-8799-4cc3-9111-482da0671ee9","searchKey1":2,"searchKey2":1,"userToken":"991174c2-7f24-4e8b-b7ce-555489b3e970","changedFields":[{"fieldName":"paymentMethodId","oldValue":null,"newValue":"d9feff72-b045-45fc-b978-47248fb10865","changeDate":"2013-11-06T18:18:03.738+05:30"}]} | 991174c2-7f24-4e8b-b7ce-555489b3e970 | 2013-11-06 18:18:03 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-06 18:18:04 | PROCESSED | 2 | 1 |
| 8 | com.ning.billing.beatrix.extbus.DefaultBusExternalEvent | {"objectId":"8eecc225-8799-4cc3-9111-482da0671ee9","objectType":"ACCOUNT","eventType":"ACCOUNT_CHANGE","accountId":"8eecc225-8799-4cc3-9111-482da0671ee9","tenantId":"d2c06716-8d4d-41eb-889f-66344046bb80"} | 991174c2-7f24-4e8b-b7ce-555489b3e970 | 2013-11-06 18:18:04 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-06 18:18:05 | PROCESSED | 2 | 1 |
| 9 | com.ning.billing.subscription.api.user.DefaultEffectiveSubscriptionEvent | {"eventId":"c8dabab3-2ead-4a61-a359-0c03fb0e4fd0","subscriptionId":"815f0950-610a-4b93-9b8a-62a489b2c34c","bundleId":"dce03ee9-ee63-449d-b67a-0822933ef543","requestedTransitionTime":"2013-11-06T12:48:05.000Z","effectiveTransitionTime":"2013-11-06T12:48:05.000Z","previousState":null,"previousPlan":null,"previousPhase":null,"previousPriceList":null,"nextState":"ACTIVE","nextPlan":"frenzo-usage-monthly","nextPhase":"frenzo-usage-monthly-evergreen","nextPriceList":"DEFAULT","totalOrdering":0,"transitionType":"CREATE","remainingEventsForUserOperation":0,"startDate":"2013-11-06T12:48:05.000Z","searchKey1":2,"searchKey2":1,"userToken":"f690bec2-b297-4a7e-bafa-ef4fcb658ef7"} | f690bec2-b297-4a7e-bafa-ef4fcb658ef7 | 2013-11-06 18:18:05 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-06 18:18:05 | PROCESSED | 2 | 1 |
| 10 | com.ning.billing.subscription.api.user.DefaultRequestedSubscriptionEvent | {"eventId":"c8dabab3-2ead-4a61-a359-0c03fb0e4fd0","subscriptionId":"815f0950-610a-4b93-9b8a-62a489b2c34c","bundleId":"dce03ee9-ee63-449d-b67a-0822933ef543","requestedTransitionTime":"2013-11-06T12:48:05.000Z","effectiveTransitionTime":"2013-11-06T12:48:05.000Z","previousState":null,"previousPlan":null,"previousPhase":null,"previousPriceList":null,"nextState":null,"nextPlan":null,"nextPhase":null,"nextPriceList":null,"totalOrdering":0,"transitionType":null,"remainingEventsForUserOperation":0,"startDate":null,"searchKey1":2,"searchKey2":1,"userToken":"f690bec2-b297-4a7e-bafa-ef4fcb658ef7"} | f690bec2-b297-4a7e-bafa-ef4fcb658ef7 | 2013-11-06 18:18:05 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-06 18:18:05 | PROCESSED | 2 | 1 |
+-----------+--------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------+---------------------+---------------------------------+---------------------------------+---------------------------+------------------+-------------+-------------+
10 rows in set (0.00 sec)

my test case logs are

/1.0/kb/accounts::BODY::{"accountId":null,"name":"2c084c68-bd60-485c-8c03-6ec06f758650","firstNameLength":null,"externalKey":"7521537b-c0be-4477-ab04-499be79a9219","email":"c3209b22-b27b-42b8-92ba-563b5d89fd1f","billCycleDayLocal":null,"currency":"INR","paymentMethodId":null,"timeZone":null,"address1":null,"address2":null,"postalCode":null,"company":null,"city":null,"state":null,"country":null,"locale":null,"phone":null,"isMigrated":false,"isNotifiedForInvoices":true,"accountBalance":null,"accountCBA":null,"auditLogs":null}
get account by externalkey {"accountId":"8eecc225-8799-4cc3-9111-482da0671ee9","name":"2c084c68-bd60-485c-8c03-6ec06f758650","firstNameLength":36,"externalKey":"7521537b-c0be-4477-ab04-499be79a9219","email":"c3209b22-b27b-42b8-92ba-563b5d89fd1f","billCycleDayLocal":0,"currency":"INR","paymentMethodId":null,"timeZone":"UTC","address1":"","address2":"","postalCode":"","company":"","city":"","state":"","country":"","locale":"","phone":"","isMigrated":false,"isNotifiedForInvoices":true,"accountBalance":null,"accountCBA":null,"auditLogs":null}
/1.0/kb/accounts/8eecc225-8799-4cc3-9111-482da0671ee9/paymentMethods::BODY::{"paymentMethodId":null,"accountId":"8eecc225-8799-4cc3-9111-482da0671ee9","isDefault":true,"pluginName":"paychamp","pluginInfo":{"externalPaymentId":null,"isDefaultPaymentMethod":null,"type":null,"ccName":null,"ccType":null,"ccExpirationMonth":null,"ccExpirationYear":null,"ccLast4":null,"address1":null,"address2":null,"city":null,"state":null,"zip":null,"country":null,"properties":null}}
get account by externalkey {"accountId":"8eecc225-8799-4cc3-9111-482da0671ee9","name":"2c084c68-bd60-485c-8c03-6ec06f758650","firstNameLength":36,"externalKey":"7521537b-c0be-4477-ab04-499be79a9219","email":"c3209b22-b27b-42b8-92ba-563b5d89fd1f","billCycleDayLocal":0,"currency":"INR","paymentMethodId":"d9feff72-b045-45fc-b978-47248fb10865","timeZone":"UTC","address1":"","address2":"","postalCode":"","company":"","city":"","state":"","country":"","locale":"","phone":"","isMigrated":false,"isNotifiedForInvoices":true,"accountBalance":null,"accountCBA":null,"auditLogs":null}
/1.0/kb/subscriptions::BODY::{"accountId":"8eecc225-8799-4cc3-9111-482da0671ee9","bundleId":null,"subscriptionId":null,"externalKey":"298a340e-7312-4dc6-8b35-67b9cdca62cc","startDate":null,"productName":"frenzo-usage","productCategory":"BASE","billingPeriod":"MONTHLY","priceList":"DEFAULT","cancelledDate":null,"chargedThroughDate":null,"billingStartDate":null,"billingEndDate":null,"events":null,"newEvents":null,"deletedEvents":null,"auditLogs":null}
-------->{"accountId":"8eecc225-8799-4cc3-9111-482da0671ee9","bundleId":"dce03ee9-ee63-449d-b67a-0822933ef543","subscriptionId":"815f0950-610a-4b93-9b8a-62a489b2c34c","externalKey":"298a340e-7312-4dc6-8b35-67b9cdca62cc","startDate":"2013-11-06","productName":"frenzo-usage","productCategory":"BASE","billingPeriod":"MONTHLY","priceList":"DEFAULT","cancelledDate":null,"chargedThroughDate":null,"billingStartDate":"2013-11-06","billingEndDate":null,"events":null,"newEvents":null,"deletedEvents":null,"auditLogs":null}

My server logs are

INFO: Starting Servlet Engine: Apache Tomcat/7.0.32
17:16:52.307 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.server.test.mode] on [com.ning.billing.server.config.KillbillServerConfig#isTestModeEnabled()]
17:16:52.315 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [true] for [killbill.server.multitenant] on [com.ning.billing.server.config.KillbillServerConfig#isMultiTenancyEnabled()]
17:16:52.503 [localhost-startStop-1] INFO c.n.jetty.core.listeners.SetupServer - Returning injector from com.ning.jetty.base.modules.BaseServerModule
17:16:53.248 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.server.test.mode] on [com.ning.billing.server.config.KillbillServerConfig#isTestModeEnabled()]
17:16:53.249 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [true] for [killbill.server.multitenant] on [com.ning.billing.server.config.KillbillServerConfig#isMultiTenancyEnabled()]
17:16:53.252 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning value [killbill] for [com.ning.jetty.jdbi.user] on [com.ning.jetty.jdbi.config.DaoConfig#getUsername()]
17:16:53.252 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [10s] for [com.ning.jetty.jdbi.connectionTimeout] on [com.ning.jetty.jdbi.config.DaoConfig#getConnectionTimeout()]
17:16:53.255 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [10] for [com.ning.jetty.jdbi.maxActive] on [com.ning.jetty.jdbi.config.DaoConfig#getMaxActive()]
17:16:53.256 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning value [killbill] for [com.ning.jetty.jdbi.password] on [com.ning.jetty.jdbi.config.DaoConfig#getPassword()]
17:16:53.257 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning value [jdbc:mysql://127.0.0.1:3306/killbill] for [com.ning.jetty.jdbi.url] on [com.ning.jetty.jdbi.config.DaoConfig#getJdbcUrl()]
17:16:53.257 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [1] for [com.ning.jetty.jdbi.minIdle] on [com.ning.jetty.jdbi.config.DaoConfig#getMinIdle()]
17:16:53.258 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [60m] for [com.ning.jetty.jdbi.idleMaxAge] on [com.ning.jetty.jdbi.config.DaoConfig#getIdleMaxAge()]
17:16:53.258 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [0m] for [com.ning.jetty.jdbi.maxConnectionAge] on [com.ning.jetty.jdbi.config.DaoConfig#getMaxConnectionAge()]
17:16:53.259 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [5m] for [com.ning.jetty.jdbi.idleConnectionTestPeriod] on [com.ning.jetty.jdbi.config.DaoConfig#getIdleConnectionTestPeriod()]
17:16:53.259 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [DEBUG] for [com.ning.jetty.jdbi.logLevel] on [com.ning.jetty.jdbi.config.DaoConfig#getLogLevel()]
17:16:53.261 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [com.ning.jetty.jdbi.RestartTransactionRunner] for [com.ning.jetty.jdbi.transactionHandler] on [com.ning.jetty.jdbi.config.DaoConfig#getTransactionHandlerClass()]
17:16:53.272 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [8080] for [com.ning.jetty.eventtracker.port] on [com.ning.jetty.eventtracker.config.TrackerConfig#getServerPort()]
17:16:53.273 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [localhost] for [com.ning.jetty.eventtracker.host] on [com.ning.jetty.eventtracker.config.TrackerConfig#getServerHost()]
17:16:53.302 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning null default value for [killbill.mail.smtp.host] on [com.ning.billing.util.email.EmailConfig#getSmtpServerName()]
17:16:53.325 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning null default value for [killbill.mail.smtp.port] on [com.ning.billing.util.email.EmailConfig#getSmtpPort()]
17:16:53.326 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.mail.smtp.auth] on [com.ning.billing.util.email.EmailConfig#useSmtpAuth()]
17:16:53.326 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning null default value for [killbill.mail.smtp.user] on [com.ning.billing.util.email.EmailConfig#getSmtpUserName()]
17:16:53.327 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning null default value for [killbill.mail.smtp.password] on [com.ning.billing.util.email.EmailConfig#getSmtpPassword()]
17:16:53.327 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [sup...@example.com] for [killbill.mail.from] on [com.ning.billing.util.email.EmailConfig#getDefaultFrom()]
17:16:53.328 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.mail.useSSL] on [com.ning.billing.util.email.EmailConfig#useSSL()]
17:16:53.328 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [Your invoice] for [killbill.mail.invoiceEmailSubject] on [com.ning.billing.util.email.EmailConfig#getInvoiceEmailSubject()]
17:16:53.348 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [/ehcache.xml] for [killbill.cache.config.location] on [com.ning.billing.util.config.CacheConfig#getCacheConfigLocation()]
17:16:53.391 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning value [file:////Users/nitinsingh/git/killbill/catalog/versionedCatalog] for [killbill.catalog.uri] on [com.ning.billing.util.config.CatalogConfig#getCatalogURI()]
17:16:53.423 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [bus_events] for [killbill.billing.persistent.bus.${instanceName}.tableName] on [com.ning.billing.bus.api.PersistentBusConfig#getTableName()]
17:16:53.424 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [bus_events_history] for [killbill.billing.persistent.bus.${instanceName}.historyTableName] on [com.ning.billing.bus.api.PersistentBusConfig#getHistoryTableName()]
17:16:53.424 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [5] for [killbill.billing.persistent.bus.${instanceName}.claimed] on [com.ning.billing.bus.api.PersistentBusConfig#getMaxEntriesClaimed()]
17:16:53.432 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [5m] for [killbill.billing.persistent.bus.${instanceName}.claim.time] on [com.ning.billing.bus.api.PersistentBusConfig#getClaimedTime()]
17:16:53.434 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [3000] for [killbill.billing.persistent.bus.${instanceName}.sleep] on [com.ning.billing.bus.api.PersistentBusConfig#getSleepTimeMs()]
17:16:53.435 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.billing.persistent.bus.${instanceName}.off] on [com.ning.billing.bus.api.PersistentBusConfig#isProcessingOff()]
17:16:53.435 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [3] for [killbill.billing.persistent.bus.${instanceName}.nbThreads] on [com.ning.billing.bus.api.PersistentBusConfig#getNbThreads()]
17:16:53.435 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.billing.persistent.bus.${instanceName}.useInflightQ] on [com.ning.billing.bus.api.PersistentBusConfig#isUsingInflightQueue()]
17:16:53.436 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [3000] for [killbill.billing.persistent.bus.${instanceName}.queue.capacity] on [com.ning.billing.bus.api.PersistentBusConfig#getQueueCapacity()]
17:16:53.436 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [7] for [killbill.billing.persistent.bus.${instanceName}.queue.prefetch] on [com.ning.billing.bus.api.PersistentBusConfig#getPrefetchEntries()]
17:16:53.473 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [notifications] for [killbill.billing.notificationq.${instanceName}.tableName] on [com.ning.billing.notificationq.api.NotificationQueueConfig#getTableName()]
17:16:53.473 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [notifications_history] for [killbill.billing.notificationq.${instanceName}.historyTableName] on [com.ning.billing.notificationq.api.NotificationQueueConfig#getHistoryTableName()]
17:16:53.474 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [7] for [killbill.billing.notificationq.${instanceName}.claimed] on [com.ning.billing.notificationq.api.NotificationQueueConfig#getMaxEntriesClaimed()]
17:16:53.503 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [5m] for [killbill.billing.notificationq.${instanceName}.claim.time] on [com.ning.billing.notificationq.api.NotificationQueueConfig#getClaimedTime()]
17:16:53.503 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [3000] for [killbill.billing.notificationq.${instanceName}.sleep] on [com.ning.billing.notificationq.api.NotificationQueueConfig#getSleepTimeMs()]
17:16:53.504 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.billing.notificationq.${instanceName}.notification.off] on [com.ning.billing.notificationq.api.NotificationQueueConfig#isProcessingOff()]
17:16:53.504 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [1] for [killbill.billing.notificationq.${instanceName}.notification.nbThreads] on [com.ning.billing.notificationq.api.NotificationQueueConfig#getNbThreads()]
17:16:53.504 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.billing.notificationq.${instanceName}.useInflightQ] on [com.ning.billing.notificationq.api.NotificationQueueConfig#isUsingInflightQueue()]
17:16:53.520 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [0] for [killbill.billing.notificationq.${instanceName}.queue.capacity] on [com.ning.billing.notificationq.api.NotificationQueueConfig#getQueueCapacity()]
17:16:53.520 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [7] for [killbill.billing.notificationq.${instanceName}.prefetch] on [com.ning.billing.notificationq.api.NotificationQueueConfig#getPrefetchEntries()]
17:16:53.564 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.invoice.emailNotificationsEnabled] on [com.ning.billing.util.config.InvoiceConfig#isEmailNotificationsEnabled()]
17:16:53.564 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [36] for [killbill.invoice.maxNumberOfMonthsInFuture] on [com.ning.billing.util.config.InvoiceConfig#getNumberOfMonthsInFuture()]
17:16:53.565 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.invoice.triggerInvoiceOnBlockingEvent] on [com.ning.billing.util.config.InvoiceConfig#isTriggerInvoiceOnBlockingEvent()]
17:16:53.587 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [com.ning.billing.invoice.template.formatters.DefaultInvoiceFormatterFactory] for [killbill.template.invoiceFormatterFactoryClass] on [com.ning.billing.util.template.translation.TranslatorConfig#getInvoiceFormatterFactoryClass()]
17:16:53.591 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [en_US] for [killbill.default.locale] on [com.ning.billing.util.template.translation.TranslatorConfig#getDefaultLocale()]
17:16:53.591 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [com/ning/billing/util/template/translation/CatalogTranslation] for [killbill.catalog.bundlePath] on [com.ning.billing.util.template.translation.TranslatorConfig#getCatalogBundlePath()]
17:16:53.591 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [com/ning/billing/util/template/translation/InvoiceTranslation] for [killbill.template.bundlePath] on [com.ning.billing.util.template.translation.TranslatorConfig#getInvoiceTemplateBundlePath()]
17:16:53.591 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [com/ning/billing/util/email/templates/HtmlInvoiceTemplate.mustache] for [killbill.template.name] on [com.ning.billing.util.template.translation.TranslatorConfig#getTemplateName()]
17:16:53.592 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [com/ning/billing/util/email/templates/HtmlInvoiceTemplate.mustache] for [killbill.manualPayTemplate.name] on [com.ning.billing.util.template.translation.TranslatorConfig#getManualPayTemplateName()]
17:16:53.681 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [10] for [killbill.payment.plugin.threads.nb] on [com.ning.billing.util.config.PaymentConfig#getPaymentPluginThreadNb()]
17:16:53.682 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [__external_payment__] for [killbill.payment.provider.default] on [com.ning.billing.util.config.PaymentConfig#getDefaultPaymentProvider()]
17:16:53.683 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [8,8,8] for [killbill.payment.retry.days] on [com.ning.billing.util.config.PaymentConfig#getPaymentRetryDays()]
17:16:53.684 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [300] for [killbill.payment.failure.retry.start.sec] on [com.ning.billing.util.config.PaymentConfig#getPluginFailureRetryStart()]
17:16:53.684 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [2] for [killbill.payment.failure.retry.multiplier] on [com.ning.billing.util.config.PaymentConfig#getPluginFailureRetryMultiplier()]
17:16:53.684 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [8] for [killbill.payment.failure.retry.max.attempts] on [com.ning.billing.util.config.PaymentConfig#getPluginFailureRetryMaxAttempts()]
17:16:53.687 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [90s] for [killbill.payment.plugin.timeout] on [com.ning.billing.util.config.PaymentConfig#getPaymentPluginTimeout()]
17:16:53.687 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.payment.off] on [com.ning.billing.util.config.PaymentConfig#isPaymentOff()]
17:16:53.756 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [bus_events] for [killbill.billing.persistent.bus.${instanceName}.tableName] on [com.ning.billing.bus.api.PersistentBusConfig#getTableName()]
17:16:53.757 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [bus_events_history] for [killbill.billing.persistent.bus.${instanceName}.historyTableName] on [com.ning.billing.bus.api.PersistentBusConfig#getHistoryTableName()]
17:16:53.757 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [5] for [killbill.billing.persistent.bus.${instanceName}.claimed] on [com.ning.billing.bus.api.PersistentBusConfig#getMaxEntriesClaimed()]
17:16:53.758 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [5m] for [killbill.billing.persistent.bus.${instanceName}.claim.time] on [com.ning.billing.bus.api.PersistentBusConfig#getClaimedTime()]
17:16:53.758 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [3000] for [killbill.billing.persistent.bus.${instanceName}.sleep] on [com.ning.billing.bus.api.PersistentBusConfig#getSleepTimeMs()]
17:16:53.759 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.billing.persistent.bus.${instanceName}.off] on [com.ning.billing.bus.api.PersistentBusConfig#isProcessingOff()]
17:16:53.760 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [3] for [killbill.billing.persistent.bus.${instanceName}.nbThreads] on [com.ning.billing.bus.api.PersistentBusConfig#getNbThreads()]
17:16:53.760 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.billing.persistent.bus.${instanceName}.useInflightQ] on [com.ning.billing.bus.api.PersistentBusConfig#isUsingInflightQueue()]
17:16:53.760 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [3000] for [killbill.billing.persistent.bus.${instanceName}.queue.capacity] on [com.ning.billing.bus.api.PersistentBusConfig#getQueueCapacity()]
17:16:53.761 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [7] for [killbill.billing.persistent.bus.${instanceName}.queue.prefetch] on [com.ning.billing.bus.api.PersistentBusConfig#getPrefetchEntries()]
17:16:53.778 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [NoOverdueConfig.xml] for [killbill.overdue.uri] on [com.ning.billing.overdue.OverdueProperties#getConfigURI()]
17:16:53.816 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [killbill-currency-plugin] for [killbill.currency.provider.default] on [com.ning.billing.util.config.CurrencyConfig#getDefaultCurrencyProvider()]
17:16:53.861 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [killbill.properties] for [killbill.osgi.bundle.property.name] on [com.ning.billing.util.config.OSGIConfig#getOSGIKillbillPropertyName()]
17:16:53.861 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [/var/tmp/felix] for [killbill.osgi.root.dir] on [com.ning.billing.util.config.OSGIConfig#getOSGIBundleRootDir()]
17:16:53.862 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [osgi-cache] for [killbill.osgi.bundle.cache.name] on [com.ning.billing.util.config.OSGIConfig#getOSGIBundleCacheName()]
17:16:53.862 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [/var/tmp/bundles] for [killbill.osgi.bundle.install.dir] on [com.ning.billing.util.config.OSGIConfig#getRootInstallationDir()]
17:16:53.863 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [com.ning.billing.account.api,com.ning.billing.analytics.api.sanity,com.ning.billing.analytics.api.user,com.ning.billing.beatrix.bus.api,com.ning.billing.catalog.api,com.ning.billing.invoice.api,com.ning.billing.entitlement.api,com.ning.billing,com.ning.billing.notification.api,com.ning.billing.notification.plugin.api,com.ning.billing.osgi.api,com.ning.billing.osgi.api.config,com.ning.billing.overdue,com.ning.billing.payment.api,com.ning.billing.payment.plugin.api,com.ning.billing.tenant.api,com.ning.billing.usage.api,com.ning.billing.util.api,com.ning.billing.util.audit,com.ning.billing.util.callcontext,com.ning.billing.util.customfield,com.ning.billing.notification.plugin,com.ning.billing.currency.plugin.api,com.ning.billing.currency.api,com.ning.billing.util.email,com.ning.billing.util.entity,com.ning.billing.util.tag,com.ning.billing.util.template,com.ning.billing.util.template.translation,sun.misc,javax.management,javax.servlet;version=3.0,javax.servlet.http;version=3.0,org.joda.time;org.joda.time.format;version=2.1,org.osgi.service.log;version=1.3,org.osgi.service.http,org.osgi.service.deploymentadmin;version=1.1.0,org.osgi.service.event;version=1.2.0,org.slf4j;version=1.7.2] for [killbill.osgi.system.bundle.export.packages] on [com.ning.billing.util.config.OSGIConfig#getSystemBundleExportPackages()]
17:16:53.869 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [root] for [com.ning.billing.osgi.jdbc.user] on [com.ning.billing.osgi.glue.OSGIDataSourceConfig#getUsername()]
17:16:53.870 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [10s] for [com.ning.billing.osgi.jdbc.connectionTimeout] on [com.ning.billing.osgi.glue.OSGIDataSourceConfig#getConnectionTimeout()]
17:16:53.870 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [10] for [com.ning.billing.osgi.jdbc.maxActive] on [com.ning.billing.osgi.glue.OSGIDataSourceConfig#getMaxActive()]
17:16:53.870 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [root] for [com.ning.billing.osgi.jdbc.password] on [com.ning.billing.osgi.glue.OSGIDataSourceConfig#getPassword()]
17:16:53.871 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [jdbc:mysql://127.0.0.1:3306/killbill] for [com.ning.billing.osgi.jdbc.url] on [com.ning.billing.osgi.glue.OSGIDataSourceConfig#getJdbcUrl()]
17:16:53.871 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [1] for [com.ning.billing.osgi.jdbc.minIdle] on [com.ning.billing.osgi.glue.OSGIDataSourceConfig#getMinIdle()]
17:16:54.093 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [1h] for [killbill.rbac.globalSessionTimeout] on [com.ning.billing.util.config.RbacConfig#getGlobalSessionTimeout()]
17:16:54.183 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [classpath:shiro.ini] for [killbill.security.shiroResourcePath] on [com.ning.billing.util.config.SecurityConfig#getShiroResourcePath()]
17:16:54.195 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning null default value for [killbill.security.ldap.userDnTemplate] on [com.ning.billing.util.config.SecurityConfig#getShiroLDAPUserDnTemplate()]
17:16:54.196 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning null default value for [killbill.security.ldap.searchBase] on [com.ning.billing.util.config.SecurityConfig#getShiroLDAPSearchBase()]
17:16:54.197 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [memberOf=uid={0}] for [killbill.security.ldap.groupSearchFilter] on [com.ning.billing.util.config.SecurityConfig#getShiroLDAPGroupSearchFilter()]
17:16:54.197 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [memberOf] for [killbill.security.ldap.groupNameId] on [com.ning.billing.util.config.SecurityConfig#getShiroLDAPGroupNameID()]
17:16:54.197 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [admin = *:*
finance = invoice:*, payment:*
support = entitlement:*, invoice:item_adjust] for [killbill.security.ldap.permissionsByGroup] on [com.ning.billing.util.config.SecurityConfig#getShiroLDAPPermissionsByGroup()]
17:16:54.198 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [ldap://127.0.0.1:389] for [killbill.security.ldap.url] on [com.ning.billing.util.config.SecurityConfig#getShiroLDAPUrl()]
17:16:54.198 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning null default value for [killbill.security.ldap.systemUsername] on [com.ning.billing.util.config.SecurityConfig#getShiroLDAPSystemUsername()]
17:16:54.198 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning null default value for [killbill.security.ldap.systemPassword] on [com.ning.billing.util.config.SecurityConfig#getShiroLDAPSystemPassword()]
17:16:54.199 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [simple] for [killbill.security.ldap.authenticationMechanism] on [com.ning.billing.util.config.SecurityConfig#getShiroLDAPAuthenticationMechanism()]
17:16:54.199 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.security.ldap.disableSSLCheck] on [com.ning.billing.util.config.SecurityConfig#disableShiroLDAPSSLCheck()]
17:16:56.665 [localhost-startStop-1] INFO com.mchange.v2.log.MLog - MLog clients using java 1.4+ standard logging.
17:16:56.813 [localhost-startStop-1] INFO com.mchange.v2.c3p0.C3P0Registry - Initializing c3p0-0.9.2 [built 09-February-2013 02:13:17 +0000; debug? true; trace: 10]
17:16:57.009 [localhost-startStop-1] INFO c.n.b.server.modules.DBIProvider - Using com.ning.jetty.jdbi.RestartTransactionRunner as a transaction handler class
17:16:58.173 [localhost-startStop-1] INFO c.n.b.p.p.DefaultPaymentProviderPluginRegistry - DefaultPaymentProviderPluginRegistry registering service __EXTERNAL_PAYMENT__
17:16:58.924 [localhost-startStop-1] INFO c.n.b.s.l.KillbillGuiceListener - KillbillLifecycleListener : contextInitialized
17:16:58.971 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle firing stage LOAD_CATALOG
17:16:58.973 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler loadCatalog for service catalog-service
17:16:59.020 [localhost-startStop-1] INFO c.n.b.util.config.catalog.XMLLoader - Initializing an object of class com.ning.billing.catalog.StandaloneCatalog from xml file at: file:////Users/nitinsingh/git/killbill/catalog/versionedCatalog/aclcatalog-1.xml
17:16:59.435 [localhost-startStop-1] INFO c.n.b.util.config.catalog.XMLLoader - Errors: 0 for file:////Users/nitinsingh/git/killbill/catalog/versionedCatalog/aclcatalog-1.xml
17:16:59.435 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler loadConfig for service overdue-service
17:16:59.435 [localhost-startStop-1] INFO c.n.b.util.config.catalog.XMLLoader - Initializing an object of class com.ning.billing.overdue.config.OverdueConfig from xml file at: NoOverdueConfig.xml
17:16:59.548 [localhost-startStop-1] INFO c.n.b.util.config.catalog.XMLLoader - Errors: 0 for NoOverdueConfig.xml
17:16:59.549 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle firing stage INIT_BUS
17:16:59.549 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler startBus for service beatrix-service
17:16:59.590 [localhost-startStop-1] INFO c.m.v.c.i.AbstractPoolBackedDataSource - Initializing c3p0 pool... com.mchange.v2.c3p0.ComboPooledDataSource [ acquireIncrement -> 3, acquireRetryAttempts -> 30, acquireRetryDelay -> 1000, autoCommitOnClose -> false, automaticTestTable -> null, breakAfterAcquireFailure -> false, checkoutTimeout -> 10000, connectionCustomizerClassName -> null, connectionTesterClassName -> com.mchange.v2.c3p0.impl.DefaultConnectionTester, dataSourceName -> 2rvz3r8ycjuvmi1yefzdq|2142c63f, debugUnreturnedConnectionStackTraces -> false, description -> null, driverClass -> null, factoryClassLocation -> null, forceIgnoreUnresolvedTransactions -> false, identityToken -> 2rvz3r8ycjuvmi1yefzdq|2142c63f, idleConnectionTestPeriod -> 300, initialPoolSize -> 3, jdbcUrl -> jdbc:mysql://127.0.0.1:3306/killbill, maxAdministrativeTaskTime -> 0, maxConnectionAge -> 0, maxIdleTime -> 3600, maxIdleTimeExcessConnections -> 0, maxPoolSize -> 10, maxStatements -> 0, maxStatementsPerConnection -> 0, minPoolSize -> 1, numHelperThreads -> 3, preferredTestQuery -> null, properties -> {user=******, password=******}, propertyCycle -> 0, statementCacheNumDeferredCloseThreads -> 0, testConnectionOnCheckin -> false, testConnectionOnCheckout -> false, unreturnedConnectionTimeout -> 0, userOverrides -> {}, usesTraditionalReflectiveProxies -> false ]
17:17:00.163 [localhost-startStop-1] INFO com.ning.billing.queue.DBBackedQueue - DBBackedQueue-bus-bus_events: Initialized with isQueueOpenForWrite = true, isQueueOpenForReadtrue
17:17:00.164 [localhost-startStop-1] INFO c.n.b.queue.DefaultQueueLifecycle - Bus: Starting with 3 threads
17:17:00.165 [bus-th] INFO c.n.b.queue.DefaultQueueLifecycle - Bus: Thread bus-th [32] starting
17:17:00.168 [bus-th] INFO c.n.b.queue.DefaultQueueLifecycle - Bus: Thread bus-th [33] starting
17:17:00.171 [bus-th] INFO c.n.b.queue.DefaultQueueLifecycle - Bus: Thread bus-th [34] starting
17:17:00.176 [localhost-startStop-1] INFO c.n.b.queue.DefaultQueueLifecycle - Bus: Done waiting for all threads to be started, got 3/3
17:17:00.177 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler startBus for service bus-service
17:17:00.404 [localhost-startStop-1] INFO com.ning.billing.queue.DBBackedQueue - DBBackedQueue-bus-bus_events: Initialized with isQueueOpenForWrite = true, isQueueOpenForReadtrue
17:17:00.404 [localhost-startStop-1] INFO c.n.b.queue.DefaultQueueLifecycle - Bus: Starting with 3 threads
17:17:00.407 [bus-th] INFO c.n.b.queue.DefaultQueueLifecycle - Bus: Thread bus-th [35] starting
17:17:00.494 [bus-th] INFO c.n.b.queue.DefaultQueueLifecycle - Bus: Thread bus-th [36] starting
17:17:00.509 [bus-th] INFO c.n.b.queue.DefaultQueueLifecycle - Bus: Thread bus-th [37] starting
17:17:00.516 [localhost-startStop-1] INFO c.n.b.queue.DefaultQueueLifecycle - Bus: Done waiting for all threads to be started, got 3/3
17:17:00.516 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle firing stage INIT_PLUGIN
17:17:00.516 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler initialize for service osgi-service
17:17:00.517 [localhost-startStop-1] INFO c.n.billing.osgi.DefaultOSGIService - Deleted recursively /var/tmp/felix/osgi-cache/bundle0
17:17:00.518 [localhost-startStop-1] INFO c.n.billing.osgi.DefaultOSGIService - Deleted recursively /var/tmp/felix/osgi-cache/bundle1/version0.0
17:17:00.518 [localhost-startStop-1] INFO c.n.billing.osgi.DefaultOSGIService - Deleted recursively /var/tmp/felix/osgi-cache/bundle1
17:17:00.519 [localhost-startStop-1] INFO c.n.billing.osgi.DefaultOSGIService - Deleted recursively /var/tmp/felix/osgi-cache
17:17:00.758 [localhost-startStop-1] WARN com.ning.billing.osgi.FileInstall - Unable to find the JRuby bundle at /var/tmp/bundles/platform/jruby.jar, ruby plugins won't be started!
17:17:00.759 [localhost-startStop-1] INFO com.ning.billing.osgi.FileInstall - Installing Java OSGI bundle from /var/tmp/bundles/platform/ccb-killbill-plugin-0.0.1-SNAPSHOT.jar
17:17:00.998 [localhost-startStop-1] WARN c.n.b.osgi.pluginconf.PluginFinder - Configuration root dir /var/tmp/bundles/plugins/ruby is not a valid directory
17:17:00.998 [localhost-startStop-1] WARN c.n.b.osgi.pluginconf.PluginFinder - Configuration root dir /var/tmp/bundles/plugins/java is not a valid directory
17:17:00.998 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle firing stage INIT_SERVICE
17:17:00.998 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler registerForNotifications for service beatrix-service
17:17:00.998 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler initialize for service payment-service
17:17:01.000 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler initialize for service invoice-service
17:17:01.001 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler initialize for service overdue-service
17:17:01.002 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler initialize for service subscription-service
17:17:01.002 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler registerForNotifications for service server-service
17:17:01.003 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler initialize for service security-service
17:17:01.004 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle firing stage START_PLUGIN
17:17:01.004 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler start for service osgi-service
17:17:01.004 [localhost-startStop-1] INFO com.ning.billing.osgi.FileInstall - Starting bundle file:/var/tmp/bundles/platform/ccb-killbill-plugin-0.0.1-SNAPSHOT.jar
Starting to listen for service events.
17:17:01.099 [localhost-startStop-1] INFO c.n.b.p.p.DefaultPaymentProviderPluginRegistry - DefaultPaymentProviderPluginRegistry registering service paychamp
CCB_PLUGIN STARTED
17:17:01.100 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle firing stage START_SERVICE
17:17:01.100 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler start for service payment-service
17:17:01.121 [localhost-startStop-1] INFO c.n.b.queue.DefaultQueueLifecycle - NotificationQ: Starting with 1 threads
17:17:01.122 [Notification-queue-dispatch] INFO c.n.b.queue.DefaultQueueLifecycle - NotificationQ: Thread Notification-queue-dispatch [40] starting
17:17:01.191 [localhost-startStop-1] INFO c.n.b.queue.DefaultQueueLifecycle - NotificationQ: Done waiting for all threads to be started, got 1/1
17:17:01.191 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler start for service invoice-service
17:17:01.191 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler start for service overdue-service
17:17:01.192 [localhost-startStop-1] INFO c.n.b.b.lifecycle.DefaultLifecycle - Killbill lifecycle calling handler start for service subscription-service
17:17:01.198 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [false] for [killbill.server.updateCheck.skip] on [com.ning.billing.server.config.UpdateCheckConfig#shouldSkipUpdateCheck()]
17:17:01.204 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [https://raw.github.com/killbill/killbill/master/server/src/main/resources/update-checker/killbill-server-update-list.properties] for [killbill.server.updateCheck.url] on [com.ning.billing.server.config.UpdateCheckConfig#updateCheckURL()]
17:17:01.205 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [3000] for [killbill.server.updateCheck.connectTimeout] on [com.ning.billing.server.config.UpdateCheckConfig#updateCheckConnectionTimeout()]
17:17:01.235 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning value [killbill] for [com.ning.jetty.jdbi.user] on [com.ning.jetty.jdbi.config.DaoConfig#getUsername()]
17:17:01.235 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [10s] for [com.ning.jetty.jdbi.connectionTimeout] on [com.ning.jetty.jdbi.config.DaoConfig#getConnectionTimeout()]
17:17:01.235 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [10] for [com.ning.jetty.jdbi.maxActive] on [com.ning.jetty.jdbi.config.DaoConfig#getMaxActive()]
17:17:01.236 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning value [killbill] for [com.ning.jetty.jdbi.password] on [com.ning.jetty.jdbi.config.DaoConfig#getPassword()]
17:17:01.236 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning value [jdbc:mysql://127.0.0.1:3306/killbill] for [com.ning.jetty.jdbi.url] on [com.ning.jetty.jdbi.config.DaoConfig#getJdbcUrl()]
17:17:01.236 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [1] for [com.ning.jetty.jdbi.minIdle] on [com.ning.jetty.jdbi.config.DaoConfig#getMinIdle()]
17:17:01.236 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [60m] for [com.ning.jetty.jdbi.idleMaxAge] on [com.ning.jetty.jdbi.config.DaoConfig#getIdleMaxAge()]
17:17:01.237 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [0m] for [com.ning.jetty.jdbi.maxConnectionAge] on [com.ning.jetty.jdbi.config.DaoConfig#getMaxConnectionAge()]
17:17:01.237 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [5m] for [com.ning.jetty.jdbi.idleConnectionTestPeriod] on [com.ning.jetty.jdbi.config.DaoConfig#getIdleConnectionTestPeriod()]
17:17:01.237 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [DEBUG] for [com.ning.jetty.jdbi.logLevel] on [com.ning.jetty.jdbi.config.DaoConfig#getLogLevel()]
17:17:01.237 [localhost-startStop-1] INFO o.s.c.ConfigurationObjectFactory - Assigning default value [com.ning.jetty.jdbi.RestartTransactionRunner] for [com.ning.jetty.jdbi.transactionHandler] on [com.ning.jetty.jdbi.config.DaoConfig#getTransactionHandlerClass()]
17:17:01.453 [localhost-startStop-1] INFO c.s.j.a.core.PackagesResourceConfig - Scanning for root resource and provider classes in the packages:
com.ning.billing.jaxrs.mappers
com.ning.billing.jaxrs.resources
17:17:01.637 [localhost-startStop-1] INFO c.s.j.a.core.ScanningResourceConfig - Root resource classes found:
class com.ning.billing.jaxrs.resources.SubscriptionResource
class com.ning.billing.jaxrs.resources.PaymentResource
class com.ning.billing.jaxrs.resources.InvoiceResource
class com.ning.billing.jaxrs.resources.AccountResource
class com.ning.billing.jaxrs.resources.TagResource
class com.ning.billing.jaxrs.resources.TenantResource
class com.ning.billing.jaxrs.resources.PluginResource
class com.ning.billing.jaxrs.resources.SecurityResource
class com.ning.billing.jaxrs.resources.CatalogResource
class com.ning.billing.jaxrs.resources.TestResource
class com.ning.billing.jaxrs.resources.RefundResource
class com.ning.billing.jaxrs.resources.PaymentMethodResource
class com.ning.billing.jaxrs.resources.ExportResource
class com.ning.billing.jaxrs.resources.CreditResource
class com.ning.billing.jaxrs.resources.BundleResource
class com.ning.billing.jaxrs.resources.ChargebackResource
17:17:01.637 [localhost-startStop-1] INFO c.s.j.a.core.ScanningResourceConfig - Provider classes found:
class com.ning.billing.jaxrs.mappers.SubscriptionRepairExceptionMapper
class com.ning.billing.jaxrs.mappers.OverdueApiExceptionMapper
class com.ning.billing.jaxrs.mappers.BlockingApiExceptionMapper
class com.ning.billing.jaxrs.mappers.SubscriptionBillingApiExceptionMapper
class com.ning.billing.jaxrs.mappers.ShiroExceptionMapper
class com.ning.billing.jaxrs.mappers.AccountApiExceptionMapper
class com.ning.billing.jaxrs.mappers.EntitlementApiExceptionMapper
class com.ning.billing.jaxrs.mappers.RuntimeExceptionMapper
class com.ning.billing.jaxrs.mappers.EmailApiExceptionMapper
class com.ning.billing.jaxrs.mappers.IllegalPlanChangeMapper
class com.ning.billing.jaxrs.mappers.TagApiExceptionMapper
class com.ning.billing.jaxrs.mappers.CurrencyValueNullMapper
class com.ning.billing.jaxrs.mappers.TagDefinitionApiExceptionMapper
class com.ning.billing.jaxrs.mappers.EntityPersistenceExceptionMapper
class com.ning.billing.jaxrs.mappers.PaymentApiExceptionMapper
class com.ning.billing.jaxrs.mappers.SubscriptionApiExceptionMapper
class com.ning.billing.jaxrs.mappers.IllegalArgumentExceptionMapper
class com.ning.billing.jaxrs.mappers.OverdueErrorMapper
class com.ning.billing.jaxrs.mappers.CatalogApiExceptionMapper
class com.ning.billing.jaxrs.mappers.BillingExceptionBaseMapper
class com.ning.billing.jaxrs.mappers.InvoiceApiExceptionMapper
17:17:01.952 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.fasterxml.jackson.jaxrs.json.JacksonJsonProvider as a provider class
17:17:01.953 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.AccountResource as a root resource class
17:17:01.953 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.BundleResource as a root resource class
17:17:01.953 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.SubscriptionResource as a root resource class
17:17:01.953 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.InvoiceResource as a root resource class
17:17:01.953 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.TagResource as a root resource class
17:17:01.953 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.CatalogResource as a root resource class
17:17:01.953 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.PaymentMethodResource as a root resource class
17:17:01.954 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.PaymentResource as a root resource class
17:17:01.954 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.PluginResource as a root resource class
17:17:01.954 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.RefundResource as a root resource class
17:17:01.954 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.TenantResource as a root resource class
17:17:01.954 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Registering com.ning.billing.jaxrs.resources.ExportResource as a root resource class
17:17:01.962 [localhost-startStop-1] INFO c.s.j.s.i.a.WebApplicationImpl - Initiating Jersey application, version 'Jersey: 1.12 02/15/2012 04:51 PM'
17:17:02.242 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.fasterxml.jackson.jaxrs.json.JacksonJsonProvider to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.132 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.AccountResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.147 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.BundleResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.153 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.CatalogResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.170 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.ChargebackResource to GuiceInstantiatedComponentProvider
17:17:03.193 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.CreditResource to GuiceInstantiatedComponentProvider
17:17:03.200 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.ExportResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.223 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.InvoiceResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.230 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.PaymentMethodResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.245 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.PaymentResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.258 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.PluginResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.261 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.RefundResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.271 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.SecurityResource to GuiceInstantiatedComponentProvider
17:17:03.395 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.SubscriptionResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.400 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.TagResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.418 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.TenantResource to GuiceManagedComponentProvider with the scope "Singleton"
17:17:03.427 [localhost-startStop-1] INFO c.s.j.g.s.c.GuiceComponentProviderFactory - Binding com.ning.billing.jaxrs.resources.TestResource to GuiceInstantiatedComponentProvider
17:17:03.486 [localhost-startStop-1] INFO c.n.b.s.filters.KillbillGuiceFilter - Kill Bill server has started
17:17:03.487 [localhost-startStop-1] INFO c.n.b.s.updatechecker.UpdateChecker - For Kill Bill Commercial Support, visit http://thebillingproject.com or send an email to sup...@thebillingproject.com
17:17:04.268 [net.sf.ehcache.CacheManager@12da89a7] INFO net.sf.ehcache.util.UpdateChecker - New update(s) found: 2.6.5 [http://www.terracotta.org/confluence/display/release/Release+Notes+Ehcache+Core+2.6]. Please check http://ehcache.org for the latest version.
17:17:06.623 [main] INFO o.a.coyote.http11.Http11AprProtocol - Starting ProtocolHandler ["http-apr-8080"]
17:17:06.636 [main] INFO org.apache.coyote.ajp.AjpAprProtocol - Starting ProtocolHandler ["ajp-apr-8009"]
17:17:06.653 [main] INFO org.apache.catalina.startup.Catalina - Server startup in 28476 ms
17:17:06.759 [http-apr-8080-exec-2] INFO o.a.s.s.m.AbstractValidatingSessionManager - Enabling session validation scheduler...
17:18:38.256 [http-apr-8080-exec-6] INFO o.a.s.cache.ehcache.EhCacheManager - Cache with name 'shiro-activeSessionCache' does not yet exist. Creating now.
17:18:38.257 [http-apr-8080-exec-6] WARN n.s.e.config.CacheConfiguration - Cache: shiro-activeSessionCache has a maxElementsInMemory of 0. This might lead to performance degradation or OutOfMemoryError at Terracotta client.From Ehcache 2.0 onwards this has been changed to mean a store with no capacity limit. Set it to 1 if you want no elements cached in memory
17:18:38.260 [http-apr-8080-exec-6] INFO o.a.s.cache.ehcache.EhCacheManager - Added EhCache named [shiro-activeSessionCache]
17:19:28.714 [http-apr-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 1 * Server in-bound request
1 > POST http://127.0.0.1:8080/1.0/kb/tenants
1 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
1 > user-agent: curl/7.19.7 (universal-apple-darwin10.0) libcurl/7.19.7 OpenSSL/0.9.8y zlib/1.2.3
1 > host: 127.0.0.1:8080
1 > accept: */*
1 > content-type: application/json
1 > x-killbill-createdby: admin
1 > content-length: 39
1 >

17:19:29.356 [http-apr-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 1 * Server out-bound response
1 < 201
1 < Location: http://127.0.0.1:8080/1.0/kb/tenants/d2c06716-8d4d-41eb-889f-66344046bb80
1 < Content-Type: application/json
1 <

17:19:47.595 [http-apr-8080-exec-6] INFO c.s.j.a.c.filter.LoggingFilter - 2 * Server in-bound request
2 > POST http://127.0.0.1:8080/1.0/kb/accounts

2 > host: 127.0.0.1:8080
2 > content-type: application/json; charset=utf-8

2 > x-killbill-createdby: ccb
2 > x-killbill-reason: userrequest
2 > x-killbill-comment: client impletentation

2 > x-killbill-apikey: bob
2 > x-killbill-apisecret: lazar
2 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
2 > connection: keep-alive
2 > accept: */*
2 > user-agent: NING/1.0

2 > content-length: 505
2 >

17:19:47.928 [http-apr-8080-exec-6] INFO c.s.j.a.c.filter.LoggingFilter - 2 * Server out-bound response
2 < 201
2 < Location: http://127.0.0.1:8080/1.0/kb/accounts/bdcca2c3-1a3f-4299-8113-87514fa563fa
2 < Content-Type: application/json
2 <

17:19:48.233 [http-apr-8080-exec-10] INFO c.s.j.a.c.filter.LoggingFilter - 3 * Server in-bound request
3 > GET http://127.0.0.1:8080/1.0/kb/accounts?externalKey=bf336939-e229-4546-ba0f-7295c6f6640f

3 > host: 127.0.0.1:8080
3 > content-type: application/json; charset=utf-8
3 > x-killbill-createdby: ccb
3 > x-killbill-reason: userrequest
3 > x-killbill-comment: client impletentation
3 > x-killbill-apikey: bob
3 > x-killbill-apisecret: lazar
3 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
3 > connection: keep-alive
3 > accept: */*
3 > user-agent: NING/1.0
3 >

17:19:48.261 [http-apr-8080-exec-10] INFO c.s.j.a.c.filter.LoggingFilter - 3 * Server out-bound response
3 < 200
3 < Content-Type: application/json
3 <

17:19:48.667 [http-apr-8080-exec-4] INFO c.s.j.a.c.filter.LoggingFilter - 4 * Server in-bound request
4 > POST http://127.0.0.1:8080/1.0/kb/accounts/bdcca2c3-1a3f-4299-8113-87514fa563fa/paymentMethods?isDefault=true

4 > host: 127.0.0.1:8080
4 > content-type: application/json; charset=utf-8

4 > x-killbill-createdby: ccb
4 > x-killbill-reason: userrequest
4 > x-killbill-comment: client impletentation

4 > x-killbill-apikey: bob
4 > x-killbill-apisecret: lazar
4 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
4 > connection: keep-alive
4 > accept: */*
4 > user-agent: NING/1.0

4 > content-length: 391
4 >

17:19:49.024 [http-apr-8080-exec-4] INFO c.s.j.a.c.filter.LoggingFilter - 4 * Server out-bound response
4 < 201
4 < Location: http://127.0.0.1:8080/1.0/kb/paymentMethods/941a86fb-4c85-4f6c-8ae2-edcd20c9b32c
4 < Content-Type: application/json
4 <

17:19:49.359 [http-apr-8080-exec-8] INFO c.s.j.a.c.filter.LoggingFilter - 5 * Server in-bound request
5 > GET http://127.0.0.1:8080/1.0/kb/accounts?externalKey=bf336939-e229-4546-ba0f-7295c6f6640f

5 > host: 127.0.0.1:8080
5 > content-type: application/json; charset=utf-8
5 > x-killbill-createdby: ccb
5 > x-killbill-reason: userrequest
5 > x-killbill-comment: client impletentation
5 > x-killbill-apikey: bob
5 > x-killbill-apisecret: lazar
5 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
5 > connection: keep-alive
5 > accept: */*
5 > user-agent: NING/1.0
5 >

17:19:49.382 [http-apr-8080-exec-8] INFO c.s.j.a.c.filter.LoggingFilter - 5 * Server out-bound response
5 < 200
5 < Content-Type: application/json
5 <

17:19:50.730 [http-apr-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 6 * Server in-bound request
6 > POST http://127.0.0.1:8080/1.0/kb/subscriptions

6 > host: 127.0.0.1:8080
6 > content-type: application/json; charset=utf-8
6 > x-killbill-createdby: ccb
6 > x-killbill-reason: userrequest
6 > x-killbill-comment: client impletentation
6 > x-killbill-apikey: bob
6 > x-killbill-apisecret: lazar
6 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
6 > connection: keep-alive
6 > accept: */*
6 > user-agent: NING/1.0

6 > content-length: 424
6 >

17:19:51.535 [http-apr-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 6 * Server out-bound response
6 < 201
6 < Location: http://127.0.0.1:8080/1.0/kb/subscriptions/0b7ab9ac-a397-480e-8ff2-4035b17ef421
6 < Content-Type: application/json
6 <

17:19:51.842 [http-apr-8080-exec-6] INFO c.s.j.a.c.filter.LoggingFilter - 7 * Server in-bound request
7 > GET http://127.0.0.1:8080/1.0/kb/subscriptions/0b7ab9ac-a397-480e-8ff2-4035b17ef421

7 > host: 127.0.0.1:8080
7 > content-type: application/json; charset=utf-8
7 > x-killbill-createdby: ccb
7 > x-killbill-reason: userrequest
7 > x-killbill-comment: client impletentation
7 > x-killbill-apikey: bob
7 > x-killbill-apisecret: lazar
7 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
7 > connection: keep-alive
7 > accept: */*
7 > user-agent: NING/1.0
7 >

17:19:52.260 [http-apr-8080-exec-6] INFO c.s.j.a.c.filter.LoggingFilter - 7 * Server out-bound response
7 < 200
7 < Content-Type: application/json
7 <

18:17:06.761 [Thread-22] INFO o.a.s.s.m.AbstractValidatingSessionManager - Validating all active sessions...
18:17:07.146 [Thread-22] INFO o.a.s.s.m.AbstractValidatingSessionManager - Finished session validation. No sessions were stopped.
18:18:02.539 [http-apr-8080-exec-10] INFO c.s.j.a.c.filter.LoggingFilter - 8 * Server in-bound request
8 > POST http://127.0.0.1:8080/1.0/kb/accounts

8 > host: 127.0.0.1:8080
8 > content-type: application/json; charset=utf-8

8 > x-killbill-createdby: ccb
8 > x-killbill-reason: userrequest
8 > x-killbill-comment: client impletentation

8 > x-killbill-apikey: bob
8 > x-killbill-apisecret: lazar
8 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
8 > connection: keep-alive
8 > accept: */*
8 > user-agent: NING/1.0

8 > content-length: 505
8 >

18:18:02.707 [http-apr-8080-exec-10] INFO c.s.j.a.c.filter.LoggingFilter - 8 * Server out-bound response
8 < 201
8 < Location: http://127.0.0.1:8080/1.0/kb/accounts/8eecc225-8799-4cc3-9111-482da0671ee9
8 < Content-Type: application/json
8 <

18:18:03.007 [http-apr-8080-exec-4] INFO c.s.j.a.c.filter.LoggingFilter - 9 * Server in-bound request
9 > GET http://127.0.0.1:8080/1.0/kb/accounts?externalKey=7521537b-c0be-4477-ab04-499be79a9219

9 > host: 127.0.0.1:8080
9 > content-type: application/json; charset=utf-8
9 > x-killbill-createdby: ccb
9 > x-killbill-reason: userrequest
9 > x-killbill-comment: client impletentation
9 > x-killbill-apikey: bob
9 > x-killbill-apisecret: lazar
9 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
9 > connection: keep-alive
9 > accept: */*
9 > user-agent: NING/1.0
9 >

18:18:03.027 [http-apr-8080-exec-4] INFO c.s.j.a.c.filter.LoggingFilter - 9 * Server out-bound response
9 < 200
9 < Content-Type: application/json
9 <

18:18:03.508 [http-apr-8080-exec-8] INFO c.s.j.a.c.filter.LoggingFilter - 10 * Server in-bound request
10 > POST http://127.0.0.1:8080/1.0/kb/accounts/8eecc225-8799-4cc3-9111-482da0671ee9/paymentMethods?isDefault=true

10 > host: 127.0.0.1:8080
10 > content-type: application/json; charset=utf-8

10 > x-killbill-createdby: ccb
10 > x-killbill-reason: userrequest
10 > x-killbill-comment: client impletentation

10 > x-killbill-apikey: bob
10 > x-killbill-apisecret: lazar
10 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
10 > connection: keep-alive
10 > accept: */*
10 > user-agent: NING/1.0

10 > content-length: 391
10 >

18:18:03.746 [http-apr-8080-exec-8] INFO c.s.j.a.c.filter.LoggingFilter - 10 * Server out-bound response
10 < 201
10 < Location: http://127.0.0.1:8080/1.0/kb/paymentMethods/d9feff72-b045-45fc-b978-47248fb10865
10 < Content-Type: application/json
10 <

18:18:04.030 [http-apr-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 11 * Server in-bound request
11 > GET http://127.0.0.1:8080/1.0/kb/accounts?externalKey=7521537b-c0be-4477-ab04-499be79a9219

11 > host: 127.0.0.1:8080
11 > content-type: application/json; charset=utf-8
11 > x-killbill-createdby: ccb
11 > x-killbill-reason: userrequest
11 > x-killbill-comment: client impletentation
11 > x-killbill-apikey: bob
11 > x-killbill-apisecret: lazar
11 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
11 > connection: keep-alive
11 > accept: */*
11 > user-agent: NING/1.0
11 >

18:18:04.048 [http-apr-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 11 * Server out-bound response
11 < 200
11 < Content-Type: application/json
11 <

18:18:05.469 [http-apr-8080-exec-6] INFO c.s.j.a.c.filter.LoggingFilter - 12 * Server in-bound request
12 > POST http://127.0.0.1:8080/1.0/kb/subscriptions

12 > host: 127.0.0.1:8080
12 > content-type: application/json; charset=utf-8
12 > x-killbill-createdby: ccb
12 > x-killbill-reason: userrequest
12 > x-killbill-comment: client impletentation
12 > x-killbill-apikey: bob
12 > x-killbill-apisecret: lazar
12 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
12 > connection: keep-alive
12 > accept: */*
12 > user-agent: NING/1.0

12 > content-length: 424
12 >

18:18:05.849 [http-apr-8080-exec-6] INFO c.s.j.a.c.filter.LoggingFilter - 12 * Server out-bound response
12 < 201
12 < Location: http://127.0.0.1:8080/1.0/kb/subscriptions/815f0950-610a-4b93-9b8a-62a489b2c34c
12 < Content-Type: application/json
12 <

18:18:06.150 [http-apr-8080-exec-10] INFO c.s.j.a.c.filter.LoggingFilter - 13 * Server in-bound request
13 > GET http://127.0.0.1:8080/1.0/kb/subscriptions/815f0950-610a-4b93-9b8a-62a489b2c34c
13 > host: 127.0.0.1:8080
13 > content-type: application/json; charset=utf-8
13 > x-killbill-createdby: ccb
13 > x-killbill-reason: userrequest
13 > x-killbill-comment: client impletentation
13 > x-killbill-apikey: bob
13 > x-killbill-apisecret: lazar
13 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
13 > connection: keep-alive
13 > accept: */*
13 > user-agent: NING/1.0
13 >

18:18:06.420 [http-apr-8080-exec-10] INFO c.s.j.a.c.filter.LoggingFilter - 13 * Server out-bound response
13 < 200
13 < Content-Type: application/json
13 <

Please let me know if any more info is required.

Please help

Regards,
Nitin Singh

Stephane Brossier

unread,

Nov 6, 2013, 12:33:07 PM11/6/13

to nsi...@gmail.com, killbill...@googlegroups.com

Nitin,

I loaded the catalog you sent me in and tried your scenario:

1. Created the tenant, account, payment method as described in Kill Bill in 5' (http://docs.kill-bill.org/userguide.html#five-minutes)

2. Created 2 Subscriptions (with two different bundle externalKey), otherwise second call would fail.

As result you can see the CREATE events in subscription_events, and then for each of those subscriptions, you see that one invoice was generated automatically by the system. Finally, for each invoice you see one invoice_item of type RECURRING and matching the price of your catalog.

So everything seems to work as expected, i am confused why this is not functioning on your end? Are you seeing any exceptions as you run those curls?

Do all curl return successfully?

Stéphane

-------

Curls:

> curl -X POST -u admin:password -H 'Content-Type: application/json' -H 'X-Killbill-CreatedBy: admin' -d '{"apiKey": "bob", "apiSecret": "lazar"}' http://127.0.0.1:8080/1.0/kb/tenants

> curl -uadmin:password -H"X-Killbill-ApiKey:bob" -H"X-Killbill-ApiSecret:lazar" -X POST -H "Content-Type: application/json" -H "X-Killbill-CreatedBy: creator" --data-binary '{"name":"john","email":"jo...@foo.com","externalKey":"xfgrdsda","currency":"USD"}' http://127.0.0.1:8080/1.0/kb/accounts

> curl -uadmin:password -H"X-Killbill-ApiKey:bob" -H"X-Killbill-ApiSecret:lazar" -X POST -H "Content-Type: application/json" -H "X-Killbill-CreatedBy: creator" --data-binary '{"pluginName":"__EXTERNAL_PAYMENT__","pluginInfo":{}}' "http://127.0.0.1:8080/1.0/kb/accounts/93937906-7a80-4815-92dd-5b8a02ed90a5/paymentMethods?isDefault=true"

> curl -uadmin:password -H"X-Killbill-ApiKey:bob" -H"X-Killbill-ApiSecret:lazar" -X POST -H "Content-Type: application/json" -H "X-Killbill-CreatedBy: creator" --data-binary '{"accountId":"93937906-7a80-4815-92dd-5b8a02ed90a5","externalKey":"myBundleName","productName":"frenzo-mini","productCategory":"BASE","billingPeriod":"MONTHLY","priceList":"DEFAULT"}' "http://127.0.0.1:8080/1.0/kb/subscriptions"

> curl -uadmin:password -H"X-Killbill-ApiKey:bob" -H"X-Killbill-ApiSecret:lazar" -X POST -H "Content-Type: application/json" -H "X-Killbill-CreatedBy: creator" --data-binary '{"accountId":"93937906-7a80-4815-92dd-5b8a02ed90a5","externalKey":"myBundleNames","productName":"frenzo-mini","productCategory":"BASE","billingPeriod":"MONTHLY","priceList":"DEFAULT"}' "http://127.0.0.1:8080/1.0/kb/subscriptions"

Data in killbill db:

mysql> select record_id , event_type , user_type , effective_date , subscription_id , plan_name , phase_name from subscription_events;

+-----------+------------+-----------+---------------------+--------------------------------------+---------------------+-------------------------------+

+-----------+------------+-----------+---------------------+--------------------------------------+---------------------+-------------------------------+

+-----------+------------+-----------+---------------------+--------------------------------------+---------------------+-------------------------------+

mysql> select record_id, id, account_id invoice_date , currency from invoices;

+-----------+--------------------------------------+--------------------------------------+----------+

+-----------+--------------------------------------+--------------------------------------+----------+

| 1 | 4fd55dde-8f41-474c-8dfa-03d1ffbaea70 | 93937906-7a80-4815-92dd-5b8a02ed90a5 | USD |

| 2 | fda69470-9987-4e90-95ea-c2c606392282 | 93937906-7a80-4815-92dd-5b8a02ed90a5 | USD |

+-----------+--------------------------------------+--------------------------------------+----------+

mysql> select record_id , id, type, invoice_id , account_id , phase_name , amount, currency from invoice_items;

+-----------+--------------------------------------+-----------+--------------------------------------+--------------------------------------+-------------------------------+----------+----------+

+-----------+--------------------------------------+-----------+--------------------------------------+--------------------------------------+-------------------------------+----------+----------+

+-----------+--------------------------------------+-----------+--------------------------------------+--------------------------------------+-------------------------------+----------+----------+

To view this discussion on the web visit https://groups.google.com/d/msgid/killbilling-users/fe6a80c7-e99f-4a26-91f1-30109bb66fc8%40googlegroups.com.

Stephane Brossier

unread,

Nov 6, 2013, 8:03:50 PM11/6/13

to nsi...@gmail.com, killbill...@googlegroups.com

Something else i thought of to help you debug;

You could add a log.info in file

* https://github.com/killbill/killbill/blob/master/invoice/src/main/java/com/ning/billing/invoice/InvoiceListener.java in handleSubscriptionTransition line 77 to make sure invoice gets the event bus required to trigger the invoice generation

* https://github.com/killbill/killbill/blob/master/invoice/src/main/java/com/ning/billing/invoice/InvoiceDispatcher.java in processAccountWithLock line 170 to make we are indeed entering into invoice generation. Thenyou could add more log line with that same method, if you at least go to that point.

Let us know about your findings,

S.

nsi...@gmail.com

unread,

Nov 7, 2013, 1:53:19 AM11/7/13

to killbill...@googlegroups.com, nsi...@gmail.com

I have placed logs in invoice listener and invoice dispatcher and found that invoice creation event has been posted to bus event but invoice handler is not receiving the event. Where as db shows event as processed.

mysql> SELECT * FROM bus_events_history b where record_id=90;
+-----------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------+---------------------+---------------------------------+---------------------------------+---------------------------+------------------+-------------+-------------+

+-----------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------+---------------------+---------------------------------+---------------------------------+---------------------------+------------------+-------------+-------------+
| 90 | com.ning.billing.invoice.api.user.DefaultInvoiceCreationEvent | {"invoiceId":"56e77a3f-0c3e-42d3-8fee-c78be0bf5de2","accountId":"06ff8ec5-2517-4a54-b6fb-b4854180c3d0","amountOwed":5.00,"currency":"INR","searchKey1":11,"searchKey2":1,"userToken":"f6dc48d2-8f88-4df5-a0df-b76a6296b35b"} | f6dc48d2-8f88-4df5-a0df-b76a6296b35b | 2013-11-07 12:05:03 | nitinsingh-mac.acl-wireless.com | nitinsingh-mac.acl-wireless.com | 2013-11-07 12:05:04 | PROCESSED | 11 | 1 |
+-----------+---------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------+---------------------+---------------------------------+---------------------------------+---------------------------+------------------+-------------+-------------+
1 row in set (0.00 sec)

first time on successful payment show

12:03:54.911 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - Generated invoice 6ab49726-2de6-462d-8477-7e2b9c0654f2 with 1 items for accountId 227bf7bc-3554-4b95-9e81-ef9743335a2d and targetDate 2013-11-07 (targetDateTime 2013-11-07T06:33:53.000Z)
12:03:55.177 [bus-th] INFO c.n.b.i.n.DefaultNextBillingDatePoster - Queuing next billing date notification at 2013-12-07T06:33:53.000Z for subscriptionId b44d36ce-f8f1-4e32-ab68-4abc1e94dc50
12:03:55.373 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - DefaultInvoiceCreationEvent for 6ab49726-2de6-462d-8477-7e2b9c0654f2
12:03:55.373 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - post InvoiceInternalEvent event
12:03:56.175 [bus-th] INFO c.n.b.payment.bus.InvoiceHandler - Received invoice creation notification for account 227bf7bc-3554-4b95-9e81-ef9743335a2d and invoice 6ab49726-2de6-462d-8477-7e2b9c0654f2
DO PAYMENT OF 227bf7bc-3554-4b95-9e81-ef9743335a2d::0c694264-f45f-443f-b67e-07ea185ac853::5.00

while second time

12:05:03.539 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - Generated invoice 56e77a3f-0c3e-42d3-8fee-c78be0bf5de2 with 1 items for accountId 06ff8ec5-2517-4a54-b6fb-b4854180c3d0 and targetDate 2013-11-07 (targetDateTime 2013-11-07T06:35:01.000Z)
12:05:03.779 [bus-th] INFO c.n.b.i.n.DefaultNextBillingDatePoster - Queuing next billing date notification at 2013-12-07T06:35:01.000Z for subscriptionId 2bf5d487-7055-4ebc-b3a7-9504681c00b1
12:05:03.957 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - DefaultInvoiceCreationEvent for 56e77a3f-0c3e-42d3-8fee-c78be0bf5de2
12:05:03.957 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - post InvoiceInternalEvent event

so c.n.b.payment.bus.InvoiceHandler - Received invoice creation notification is missing

regards,
Nitin

nsi...@gmail.com

unread,

Nov 7, 2013, 1:56:33 AM11/7/13

to killbill...@googlegroups.com, nsi...@gmail.com

On Thursday, October 31, 2013 5:37:40 PM UTC+5:30, nsi...@gmail.com wrote:

Third iteration again successful
12:24:30.478 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - Generated invoice ae3b8153-3a8a-40af-9fa5-2ea037e16229 with 1 items for accountId 2ffae941-8a18-48b9-845b-58b2e3b76ed2 and targetDate 2013-11-07 (targetDateTime 2013-11-07T06:54:28.000Z)
12:24:30.681 [bus-th] INFO c.n.b.i.n.DefaultNextBillingDatePoster - Queuing next billing date notification at 2013-12-07T06:54:28.000Z for subscriptionId 5cc31f21-3399-4f99-a6c2-586be82f70fb
12:24:30.873 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - DefaultInvoiceCreationEvent for ae3b8153-3a8a-40af-9fa5-2ea037e16229
12:24:30.873 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - post InvoiceInternalEvent event
12:24:31.143 [bus-th] INFO c.n.b.payment.bus.InvoiceHandler - Received invoice creation notification for account 2ffae941-8a18-48b9-845b-58b2e3b76ed2 and invoice ae3b8153-3a8a-40af-9fa5-2ea037e16229
DO PAYMENT OF 2ffae941-8a18-48b9-845b-58b2e3b76ed2::183867a7-1897-48f3-8bd4-5a75dbc3eba0::5.00

Therefore I doubt on the bus event processing status. When it is marked processed?

regards,
Nitin

nsi...@gmail.com

unread,

Nov 7, 2013, 2:07:23 AM11/7/13

to killbill...@googlegroups.com, nsi...@gmail.com

Fourth iteration shows no invoice logs bus_event_history table shows only account creation, change, DefaultEffectiveSubscriptionEvent and DefaultRequestedSubscriptionEvent all marked processed. There is no invoice event in the table like in previous iterations. There are No exceptions. I am using new account in each iteration and tomcat 7.0.32 as web server. I cannot full log as attach attachments on this forum please let me know where to send attachments.

12:26:51.455 [http-apr-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 25 * Server in-bound request
25 > POST http://127.0.0.1:8080/1.0/kb/accounts
25 > host: 127.0.0.1:8080
25 > content-type: application/json; charset=utf-8
25 > x-killbill-createdby: ccb
25 > x-killbill-reason: userrequest
25 > x-killbill-comment: client impletentation
25 > x-killbill-apikey: bob
25 > x-killbill-apisecret: lazar
25 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
25 > connection: keep-alive
25 > accept: */*
25 > user-agent: NING/1.0
25 > content-length: 505
25 >

12:26:51.617 [http-apr-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 25 * Server out-bound response
25 < 201
25 < Location: http://127.0.0.1:8080/1.0/kb/accounts/7cd38013-c87a-481e-a83d-b53062c18712
25 < Content-Type: application/json
25 <

12:26:51.910 [http-apr-8080-exec-6] INFO c.s.j.a.c.filter.LoggingFilter - 26 * Server in-bound request
26 > GET http://127.0.0.1:8080/1.0/kb/accounts?externalKey=601bf69b-bc95-4a34-9f0b-820f7fa65a7c
26 > host: 127.0.0.1:8080
26 > content-type: application/json; charset=utf-8
26 > x-killbill-createdby: ccb
26 > x-killbill-reason: userrequest
26 > x-killbill-comment: client impletentation
26 > x-killbill-apikey: bob
26 > x-killbill-apisecret: lazar
26 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
26 > connection: keep-alive
26 > accept: */*
26 > user-agent: NING/1.0
26 >

12:26:51.927 [http-apr-8080-exec-6] INFO c.s.j.a.c.filter.LoggingFilter - 26 * Server out-bound response
26 < 200
26 < Content-Type: application/json
26 <

12:26:52.355 [http-apr-8080-exec-10] INFO c.s.j.a.c.filter.LoggingFilter - 27 * Server in-bound request
27 > POST http://127.0.0.1:8080/1.0/kb/accounts/7cd38013-c87a-481e-a83d-b53062c18712/paymentMethods?isDefault=true
27 > host: 127.0.0.1:8080
27 > content-type: application/json; charset=utf-8
27 > x-killbill-createdby: ccb
27 > x-killbill-reason: userrequest
27 > x-killbill-comment: client impletentation
27 > x-killbill-apikey: bob
27 > x-killbill-apisecret: lazar
27 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
27 > connection: keep-alive
27 > accept: */*
27 > user-agent: NING/1.0
27 > content-length: 391
27 >

12:26:52.626 [http-apr-8080-exec-10] INFO c.s.j.a.c.filter.LoggingFilter - 27 * Server out-bound response
27 < 201
27 < Location: http://127.0.0.1:8080/1.0/kb/paymentMethods/081f3961-225e-45c1-86bc-e32faddeeb07
27 < Content-Type: application/json
27 <

12:26:52.914 [http-apr-8080-exec-4] INFO c.s.j.a.c.filter.LoggingFilter - 28 * Server in-bound request
28 > GET http://127.0.0.1:8080/1.0/kb/accounts?externalKey=601bf69b-bc95-4a34-9f0b-820f7fa65a7c
28 > host: 127.0.0.1:8080
28 > content-type: application/json; charset=utf-8
28 > x-killbill-createdby: ccb
28 > x-killbill-reason: userrequest
28 > x-killbill-comment: client impletentation
28 > x-killbill-apikey: bob
28 > x-killbill-apisecret: lazar
28 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
28 > connection: keep-alive
28 > accept: */*
28 > user-agent: NING/1.0
28 >

12:26:52.931 [http-apr-8080-exec-4] INFO c.s.j.a.c.filter.LoggingFilter - 28 * Server out-bound response
28 < 200
28 < Content-Type: application/json
28 <

12:26:54.267 [http-apr-8080-exec-8] INFO c.s.j.a.c.filter.LoggingFilter - 29 * Server in-bound request
29 > POST http://127.0.0.1:8080/1.0/kb/subscriptions
29 > host: 127.0.0.1:8080
29 > content-type: application/json; charset=utf-8
29 > x-killbill-createdby: ccb
29 > x-killbill-reason: userrequest
29 > x-killbill-comment: client impletentation
29 > x-killbill-apikey: bob
29 > x-killbill-apisecret: lazar
29 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
29 > connection: keep-alive
29 > accept: */*
29 > user-agent: NING/1.0
29 > content-length: 424
29 >

12:26:54.615 [http-apr-8080-exec-8] INFO c.s.j.a.c.filter.LoggingFilter - 29 * Server out-bound response
29 < 201
29 < Location: http://127.0.0.1:8080/1.0/kb/subscriptions/4a36af40-8095-4951-8822-9d8190a895fd
29 < Content-Type: application/json
29 <

12:26:54.898 [http-apr-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 30 * Server in-bound request
30 > GET http://127.0.0.1:8080/1.0/kb/subscriptions/4a36af40-8095-4951-8822-9d8190a895fd
30 > host: 127.0.0.1:8080
30 > content-type: application/json; charset=utf-8
30 > x-killbill-createdby: ccb
30 > x-killbill-reason: userrequest
30 > x-killbill-comment: client impletentation
30 > x-killbill-apikey: bob
30 > x-killbill-apisecret: lazar
30 > authorization: Basic YWRtaW46cGFzc3dvcmQ=
30 > connection: keep-alive
30 > accept: */*
30 > user-agent: NING/1.0
30 >

12:26:55.125 [http-apr-8080-exec-2] INFO c.s.j.a.c.filter.LoggingFilter - 30 * Server out-bound response
30 < 200
30 < Content-Type: application/json
30 <

Pierre-Alexandre Meyer

unread,

Nov 7, 2013, 8:07:22 AM11/7/13

to Nitin Singh, killbill...@googlegroups.com

For information, I also tried your catalog a few times, with accounts in various currencies, but I couldn't reproduce it either.

On Thu, Nov 7, 2013 at 2:07 AM, <nsi...@gmail.com> wrote:

Fourth iteration shows no invoice logs bus_event_history table shows only account creation, change, DefaultEffectiveSubscriptionEvent and DefaultRequestedSubscriptionEvent all marked processed. There is no invoice event in the table like in previous iterations. There are No exceptions

Until we get access to the full logs (see separate email), to help narrow down the problem, could you try re-running your tests but without installing the ccb-killbill-plugin?

Running Kill Bill with verbose logs will also be helpful. You need to create a custom logging configuration file called logback.xml and specify its path via: -Dlogback.configurationFile=/tmp/logback.xml

Here's a working example:

<!-- encoders are assigned the type

ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->

<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>

</encoder>

</appender>

<appender-ref ref="STDOUT" />

</root>

</configuration>

--

Pierre

nsi...@gmail.com

unread,

Nov 7, 2013, 8:09:01 AM11/7/13

to killbill...@googlegroups.com, nsi...@gmail.com

On Thursday, October 31, 2013 5:37:40 PM UTC+5:30, nsi...@gmail.com wrote:

Debugging more in guava I have found that some times
DefaultEffectiveSubscriptionEvent is marked as dead event
18:30:25.264 [bus-th] INFO c.g.c.e.EventBus.Killbill EventBus - dead event class com.ning.billing.subscription.api.user.DefaultEffectiveSubscriptionEvent
Therefore no invoice is generated in this case.

when event is called

18:26:48.008 [bus-th] INFO c.g.c.e.EventBus.Killbill EventBus - dispatch called class com.ning.billing.subscription.api.user.DefaultEffectiveSubscriptionEvent
18:26:48.008 [bus-th] INFO c.n.billing.invoice.InvoiceListener - EffectiveSubscriptionInternalEvent CREATE remaining events::0

strange thing is dead event is marked when wrapper is empty in
Set<EventHandler> wrappers = handlersByType.get(eventType);

And first time I am getting a non empty wrapper resulting successful event dispatch but after that in the very next iteration wrapper is empty for the same event. I hope it's not some cache issue
Please suggest

regards,
Nitin

phoenix

unread,

Nov 7, 2013, 8:33:25 AM11/7/13

to killbill...@googlegroups.com

I'll remove the plugin, use the logback logs and will send you the logs.

Attached are the logs for 2 iteration of the same test case. I am new to guava so don't know if it's working as per its feature.

for debug

I have added log in com.google.common.eventbus.EventBus.post

if (!dispatched && !(event instanceof DeadEvent)) {

logger.info("dead event "+event.getClass());

post(new DeadEvent(this, event));

}

and log in com.google.common.eventbus.EventBus.dispatch

try {

logger.info("dispatch called "+event.getClass());

regards,

Nitin

killbill.log

Pierre-Alexandre Meyer

unread,

Nov 7, 2013, 8:52:47 AM11/7/13

to Nitin Singh, killbill...@googlegroups.com

On Thu, Nov 7, 2013 at 8:09 AM, <nsi...@gmail.com> wrote:

Debugging more in guava I have found that some times
DefaultEffectiveSubscriptionEvent is marked as dead event
18:30:25.264 [bus-th] INFO c.g.c.e.EventBus.Killbill EventBus - dead event class com.ning.billing.subscription.api.user.DefaultEffectiveSubscriptionEvent
Therefore no invoice is generated in this case.

when event is called

18:26:48.008 [bus-th] INFO c.g.c.e.EventBus.Killbill EventBus - dispatch called class com.ning.billing.subscription.api.user.DefaultEffectiveSubscriptionEvent
18:26:48.008 [bus-th] INFO c.n.billing.invoice.InvoiceListener - EffectiveSubscriptionInternalEvent CREATE remaining events::0

strange thing is dead event is marked when wrapper is empty in
Set<EventHandler> wrappers = handlersByType.get(eventType);

And first time I am getting a non empty wrapper resulting successful event dispatch but after that in the very next iteration wrapper is empty for the same event.

Which version of Java are you running?

I am currently looking at the first logs you sent.

--

Pierre

nsi...@gmail.com

unread,

Nov 7, 2013, 11:44:38 AM11/7/13

to killbill...@googlegroups.com

java version "1.6.0_65"
Java(TM) SE Runtime Environment (build 1.6.0_65-b14-462-10M4609)
Java HotSpot(TM) 64-Bit Server VM (build 20.65-b04-462, mixed mode)

nsi...@gmail.com

unread,

Nov 8, 2013, 1:05:51 AM11/8/13

to killbill...@googlegroups.com, nsi...@gmail.com

On Thursday, October 31, 2013 5:37:40 PM UTC+5:30, nsi...@gmail.com wrote:

I have noticed that EventBus.handlersByType object is changing its state at runtime which causes the problem.
key set in this map

11:24:36.273 [bus-th] INFO c.g.c.e.EventBus.Killbill EventBus - ----[interface com.ning.billing.events.BusInternalEvent, interface com.ning.billing.events.ControlTagDeletionInternalEvent, interface com.ning.billing.events.RepairSubscriptionInternalEvent, interface com.ning.billing.events.EffectiveEntitlementInternalEvent, interface com.ning.billing.events.PaymentInfoInternalEvent, interface com.ning.billing.events.InvoiceAdjustmentInternalEvent, interface com.ning.billing.events.EffectiveSubscriptionInternalEvent, interface com.ning.billing.events.BlockingTransitionInternalEvent, interface com.ning.billing.events.ControlTagCreationInternalEvent, interface com.ning.billing.events.PaymentErrorInternalEvent, interface com.ning.billing.events.InvoiceCreationInternalEvent]

changes to

11:24:37.563 [bus-th] INFO c.g.c.e.EventBus.Killbill EventBus - ----[interface com.ning.billing.notification.plugin.api.ExtBusEvent]

and after which events are turning to dead events.

regards,
Nitin

nsi...@gmail.com

unread,

Nov 8, 2013, 3:34:34 AM11/8/13

to killbill...@googlegroups.com, nsi...@gmail.com

I have found that there are muliplte instance of DefaultPersistnaceBus are created by the system the bus provider has
@Override
public PersistentBus get() {
return new DefaultPersistentBus(dbi, clock, busConfig, metricRegistry);
}
Which creates a new instance When get is called and all the events are forwarded to this new bus. Now this bus doesnot contain the old subscribers so all the events start turning to dead event.

13:17:58.963 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - class com.ning.billing.account.api.user.DefaultAccountChangeEvent doProcessEvents com.ning.billing.account.api.user.DefaultAccountChangeEvent@14cfd968
13:17:58.963 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383896839804 - hashcode 1529586214----[interface com.ning.billing.events.ControlTagDeletionInternalEvent, interface com.ning.billing.events.RepairSubscriptionInternalEvent, interface com.ning.billing.events.EffectiveSubscriptionInternalEvent, interface com.ning.billing.events.ControlTagCreationInternalEvent, interface com.ning.billing.events.BusInternalEvent, interface com.ning.billing.events.PaymentErrorInternalEvent, interface com.ning.billing.events.EffectiveEntitlementInternalEvent, interface com.ning.billing.events.BlockingTransitionInternalEvent, interface com.ning.billing.events.InvoiceAdjustmentInternalEvent, interface com.ning.billing.events.PaymentInfoInternalEvent, interface com.ning.billing.events.InvoiceCreationInternalEvent]
13:17:58.963 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383896839804 - dispatch called class com.ning.billing.account.api.user.DefaultAccountChangeEvent
13:17:58.963 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383896839804 - dispatch called class com.ning.billing.account.api.user.DefaultAccountChangeEvent
13:17:58.963 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - class com.ning.billing.invoice.api.user.DefaultInvoiceCreationEvent doProcessEvents DefaultInvoiceCreationNotification [invoiceId=98d2c41f-6af1-46b0-ab53-bc7e00523558, accountId=3b3da81b-cabe-4876-a3a5-69e3f8a79865, amountOwed=5.00, currency=INR]
13:17:58.964 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383896840830 - hashcode 209728876----[interface com.ning.billing.notification.plugin.api.ExtBusEvent]
13:17:58.964 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383896840830 - dead event class com.ning.billing.invoice.api.user.DefaultInvoiceCreationEvent
13:17:58.964 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383896840830 - hashcode 209728876----[interface com.ning.billing.notification.plugin.api.ExtBusEvent]
13:17:58.985 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent doProcessEvents DefaultBusExternalEvent{objectId=a752702d-d019-4df8-9ede-553be347afda, accountId=3b3da81b-cabe-4876-a3a5-69e3f8a79865, tenantId=d2c06716-8d4d-41eb-889f-66344046bb80, objectType=SUBSCRIPTION, eventType=SUBSCRIPTION_CREATION}
13:17:58.985 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383896840830 - hashcode 209728876----[interface com.ning.billing.notification.plugin.api.ExtBusEvent]
13:17:58.985 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383896840830 - dispatch called class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent
13:17:58.986 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383896840830 - dispatch called class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent
13:17:59.081 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - 8f683d70-e91c-4a2d-9f0e-f20481bc2518 post event class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent

Please suggest if I have some configuration issue.

regards,
Nitin

nsi...@gmail.com

unread,

Nov 8, 2013, 4:08:24 AM11/8/13

to killbill...@googlegroups.com, nsi...@gmail.com

There are multiple persistence bus but their events are mixing up. external bus are getting internal events and internal events are going in external bus.

14:16:25.316 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - class com.ning.billing.account.api.user.DefaultAccountChangeEvent doProcessEvents com.ning.billing.account.api.user.DefaultAccountChangeEvent@aab60a26
14:16:25.316 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899918044 - hashcode 486328863----[interface com.ning.billing.notification.plugin.api.ExtBusEvent]
14:16:25.316 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899918044 - dead event class com.ning.billing.account.api.user.DefaultAccountChangeEvent
14:16:25.316 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899918044 - hashcode 486328863----[interface com.ning.billing.notification.plugin.api.ExtBusEvent]
14:16:25.532 [bus-th] INFO c.n.b.i.n.DefaultNextBillingDatePoster - Queuing next billing date notification at 2013-12-08T08:46:23.000Z for subscriptionId 8f7ac480-af95-4dee-8c6c-ea01ae36b205
14:16:25.827 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - DefaultInvoiceCreationEvent for 3898f5f4-5886-4cbe-a07f-efc08a776c4c
14:16:25.827 [bus-th] INFO c.n.b.invoice.InvoiceDispatcher - post InvoiceInternalEvent event
14:16:25.833 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - 3707127a-afd1-4a16-b698-49d75d5c8476 post event class com.ning.billing.invoice.api.user.DefaultInvoiceCreationEvent
14:16:25.892 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - dispatch called class com.ning.billing.subscription.api.user.DefaultEffectiveSubscriptionEvent
14:16:25.925 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - 3707127a-afd1-4a16-b698-49d75d5c8476 post event class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent
14:16:25.925 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - dispatch called class com.ning.billing.subscription.api.user.DefaultEffectiveSubscriptionEvent
14:16:25.936 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - class com.ning.billing.subscription.api.user.DefaultRequestedSubscriptionEvent doProcessEvents DefaultRequestedSubscriptionEvent{bundleId=6c6c0ed8-e8fe-4adb-b9bd-be7d2c5bce14, totalOrdering=0, subscriptionId=8f7ac480-af95-4dee-8c6c-ea01ae36b205, eventId=561ace25-82be-47e3-ab60-a1a22171f213, requestedTransitionTime=2013-11-08T08:46:23.000Z, effectiveTransitionTime=2013-11-08T08:46:23.000Z, previousState=null, previousPriceList='null', previousPlan='null', previousPhase='null', nextState=null, nextPriceList='null', nextPlan='null', nextPhase='null', remainingEventsForUserOperation=0, transitionType=null, startDate=null}
14:16:25.937 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - hashcode 1940820101----[interface com.ning.billing.events.EffectiveEntitlementInternalEvent, interface com.ning.billing.events.BusInternalEvent, interface com.ning.billing.events.RepairSubscriptionInternalEvent, interface com.ning.billing.events.EffectiveSubscriptionInternalEvent, interface com.ning.billing.events.ControlTagCreationInternalEvent, interface com.ning.billing.events.InvoiceAdjustmentInternalEvent, interface com.ning.billing.events.ControlTagDeletionInternalEvent, interface com.ning.billing.events.PaymentErrorInternalEvent, interface com.ning.billing.events.PaymentInfoInternalEvent, interface com.ning.billing.events.InvoiceCreationInternalEvent, interface com.ning.billing.events.BlockingTransitionInternalEvent]
14:16:25.937 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - dispatch called class com.ning.billing.subscription.api.user.DefaultRequestedSubscriptionEvent
14:16:25.959 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - dispatch called class com.ning.billing.subscription.api.user.DefaultRequestedSubscriptionEvent
14:16:26.509 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - events.size() 2
14:16:26.509 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - class com.ning.billing.invoice.api.user.DefaultInvoiceCreationEvent doProcessEvents DefaultInvoiceCreationNotification [invoiceId=3898f5f4-5886-4cbe-a07f-efc08a776c4c, accountId=1c2fde12-4246-4984-a37c-46dea8446d65, amountOwed=5.00, currency=INR]
14:16:26.510 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - hashcode 1940820101----[interface com.ning.billing.events.EffectiveEntitlementInternalEvent, interface com.ning.billing.events.BusInternalEvent, interface com.ning.billing.events.RepairSubscriptionInternalEvent, interface com.ning.billing.events.EffectiveSubscriptionInternalEvent, interface com.ning.billing.events.ControlTagCreationInternalEvent, interface com.ning.billing.events.InvoiceAdjustmentInternalEvent, interface com.ning.billing.events.ControlTagDeletionInternalEvent, interface com.ning.billing.events.PaymentErrorInternalEvent, interface com.ning.billing.events.PaymentInfoInternalEvent, interface com.ning.billing.events.InvoiceCreationInternalEvent, interface com.ning.billing.events.BlockingTransitionInternalEvent]
14:16:26.510 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - dispatch called class com.ning.billing.invoice.api.user.DefaultInvoiceCreationEvent
14:16:26.512 [bus-th] INFO c.n.b.payment.bus.InvoiceHandler - Received invoice creation notification for account 1c2fde12-4246-4984-a37c-46dea8446d65 and invoice 3898f5f4-5886-4cbe-a07f-efc08a776c4c
14:16:27.456 [Plugin-th-87] INFO c.n.billing.bus.DefaultPersistentBus - 3707127a-afd1-4a16-b698-49d75d5c8476 post event class com.ning.billing.payment.api.DefaultPaymentInfoEvent
14:16:27.457 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - dispatch called class com.ning.billing.invoice.api.user.DefaultInvoiceCreationEvent
14:16:27.487 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - 3707127a-afd1-4a16-b698-49d75d5c8476 post event class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent
14:16:27.487 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - dispatch called class com.ning.billing.invoice.api.user.DefaultInvoiceCreationEvent
14:16:27.498 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent doProcessEvents DefaultBusExternalEvent{objectId=8f7ac480-af95-4dee-8c6c-ea01ae36b205, accountId=1c2fde12-4246-4984-a37c-46dea8446d65, tenantId=d2c06716-8d4d-41eb-889f-66344046bb80, objectType=SUBSCRIPTION, eventType=SUBSCRIPTION_CREATION}
14:16:27.498 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - hashcode 1940820101----[interface com.ning.billing.events.EffectiveEntitlementInternalEvent, interface com.ning.billing.events.BusInternalEvent, interface com.ning.billing.events.RepairSubscriptionInternalEvent, interface com.ning.billing.events.EffectiveSubscriptionInternalEvent, interface com.ning.billing.events.ControlTagCreationInternalEvent, interface com.ning.billing.events.InvoiceAdjustmentInternalEvent, interface com.ning.billing.events.ControlTagDeletionInternalEvent, interface com.ning.billing.events.PaymentErrorInternalEvent, interface com.ning.billing.events.PaymentInfoInternalEvent, interface com.ning.billing.events.InvoiceCreationInternalEvent, interface com.ning.billing.events.BlockingTransitionInternalEvent]
14:16:27.498 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - dead event class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent
14:16:27.499 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899893059 - hashcode 1940820101----[interface com.ning.billing.events.EffectiveEntitlementInternalEvent, interface com.ning.billing.events.BusInternalEvent, interface com.ning.billing.events.RepairSubscriptionInternalEvent, interface com.ning.billing.events.EffectiveSubscriptionInternalEvent, interface com.ning.billing.events.ControlTagCreationInternalEvent, interface com.ning.billing.events.InvoiceAdjustmentInternalEvent, interface com.ning.billing.events.ControlTagDeletionInternalEvent, interface com.ning.billing.events.PaymentErrorInternalEvent, interface com.ning.billing.events.PaymentInfoInternalEvent, interface com.ning.billing.events.InvoiceCreationInternalEvent, interface com.ning.billing.events.BlockingTransitionInternalEvent]
14:16:28.333 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - events.size() 2
14:16:28.334 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - class com.ning.billing.payment.api.DefaultPaymentInfoEvent doProcessEvents DefaultPaymentInfoEvent{accountId=1c2fde12-4246-4984-a37c-46dea8446d65, invoiceId=3898f5f4-5886-4cbe-a07f-efc08a776c4c, paymentId=783839f8-cc51-4359-8a97-3d2ece2c2992, amount=5.0000, paymentNumber=25, status=SUCCESS, effectiveDate=2013-11-08T08:46:26.000Z}
14:16:28.335 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899918044 - hashcode 486328863----[interface com.ning.billing.notification.plugin.api.ExtBusEvent]
14:16:28.335 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899918044 - dead event class com.ning.billing.payment.api.DefaultPaymentInfoEvent
14:16:28.335 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899918044 - hashcode 486328863----[interface com.ning.billing.notification.plugin.api.ExtBusEvent]
14:16:28.346 [bus-th] INFO c.n.billing.bus.DefaultPersistentBus - class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent doProcessEvents DefaultBusExternalEvent{objectId=3898f5f4-5886-4cbe-a07f-efc08a776c4c, accountId=1c2fde12-4246-4984-a37c-46dea8446d65, tenantId=d2c06716-8d4d-41eb-889f-66344046bb80, objectType=INVOICE, eventType=INVOICE_CREATION}
14:16:28.346 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899918044 - hashcode 486328863----[interface com.ning.billing.notification.plugin.api.ExtBusEvent]
14:16:28.346 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899918044 - dispatch called class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent
14:16:28.372 [bus-th] INFO c.g.c.e.E.Killbill-EventBus1383899918044 - dispatch called class com.ning.billing.beatrix.extbus.DefaultBusExternalEvent

phoenix

unread,

Nov 8, 2013, 4:44:26 AM11/8/13

to killbill...@googlegroups.com, Nitin Singh

Please find the attached logs with external payment plugin removed and using logback.xml

regards,

Nitin

kill.log

nsi...@gmail.com

unread,

Nov 8, 2013, 7:44:02 AM11/8/13

to killbill...@googlegroups.com, nsi...@gmail.com

putting
-Dkillbill.billing.persistent.bus.external.tableName=bus_ext_events -Dkillbill.billing.persistent.bus.external.historyTableName=bus_ext_events_history

has solved the issue for me.
It seems both persistence bus were using the default table but were not able to processes them.

I don't get the instance name "external" but from the test resource I found it. Please let me know if its correct.

thanks,
Nitin

Pierre-Alexandre Meyer

unread,

Nov 8, 2013, 8:55:01 AM11/8/13

to Nitin Singh, killbill...@googlegroups.com

I am still going through the latest logs you sent, but I wanted to comment on your remark below.

On Fri, Nov 8, 2013 at 7:44 AM, <nsi...@gmail.com> wrote:

putting
-Dkillbill.billing.persistent.bus.external.tableName=bus_ext_events -Dkillbill.billing.persistent.bus.external.historyTableName=bus_ext_events_history

has solved the issue for me.
It seems both persistence bus were using the default table but were not able to processes them.

Very interesting finding. Good job tracking this one down!

These properties should be set by default, but it looks like they aren't. We'll investigate.

I don't get the instance name "external" but from the test resource I found it. Please let me know if its correct.

It is correct. To give you more context, as you probably know, Kill Bill is an event-driven system: the core components communicate mainly via event triggers. For example, when an invoice is generated, a bus event is dispatched. Among listeners to that event is the payment system, which reacts to it and creates a payment.

Now, these events can be interesting for external systems as well. Maybe you need a plugin to react to invoices being generated and populate a third-party system with the invoice content for example. To separate concerns, and two make sure failures of external systems don't impact the core of the system, we decided to have two buses inside Kill Bill.

The regular ("main") internal bus is used only for internal Kill Bill systems. A second ("external") bus listens to these events and dispatch them to the external listeners.

The database tables backing up these events should be different by default but I can't think of a reason why having the same table wouldn't work. We will investigate.

--

Pierre

nsi...@gmail.com

unread,

Nov 9, 2013, 10:51:36 AM11/9/13

to killbill...@googlegroups.com

As per my understanding bus event has a map of events mapped to it and there handlers. So main bus event don't recognize external event and vice versa. Since both persistence bus pick from same table, the unrecognized events could be picked and end up dead event. That's why different set of table or some way to recognize bus required.
Regards,
Nitin

Pierre-Alexandre Meyer

unread,

Nov 10, 2013, 4:35:34 PM11/10/13

to Nitin Singh, killbill...@googlegroups.com

On Sat, Nov 9, 2013 at 10:51 AM, <nsi...@gmail.com> wrote:

As per my understanding bus event has a map of events mapped to it and there handlers. So main bus event don't recognize external event and vice versa. Since both persistence bus pick from same table, the unrecognized events could be picked and end up dead event. That's why different set of table or some way to recognize bus required.

Yes, I could see how they become "dead", but I was confused by the handlers logs you added in Guava. It looked like as if the listeners were disappearing. What was actually happening was that some log lines were referring to the main bus and others to the external one. Since the external one doesn't have any listener for internal events, the empty handlers set makes sense.

In any case, I have submitted a patch for review to set these properties as default:

https://github.com/killbill/killbill/commit/28e970996d6c2fe9618d55844755bb85a565941b