A2Billing troubleshooting – verbose logging

Sometimes it’s difficult to determine why a call is failing in A2Billing. It’s possible to turn on some very detailed logging from the A2Billing script that can often be used to track down the issue.

The option to turn on debug logging (in A2Billing v1.4+) can be found under System Settings / Global List / agi-confX. You need to turn it on for the agi-conf that your call will be using. Turn logging up to 4 like this –

a2billing AGI logging

The location of the log output can vary, mine get written to /var/log/a2billing/a2billing_agi.log.

The amount of logs written can be a little overwhelming, normally over 200 lines! However, looking towards the end of the log can often reveal the problem.

Here are a few examples.

1 – This is a SIP client making a call that failed. You can see the message saying that ‘RateEngine didnt succeed to match the dialed number’, so there’s something wrong with the rate cards –

                WHERE cc_tariffgroup.id=3 AND ((dialprefix='441604293000' OR dialprefix='44160429300' OR dialprefix='4416042930' OR dialprefix='441604293' OR dialprefix='44160429' OR dialprefix='4416042' OR dialprefix='441604' OR dialprefix='44160' OR dialprefix='4416' OR dialprefix='441' OR dialprefix='44' OR dialprefix='4' OR dialprefix='defaultprefix') OR (dialprefix LIKE '&_%' ESCAPE '&' AND '441604293000' REGEXP REPLACE(REPLACE(REPLACE(REPLACE(REPLACE(CONCAT('^', dialprefix, '$'), 'X', '[0-9]'), 'Z', '[1-9]'), 'N', '[2-9]'), '.', '.+'), '_', '')))
                AND startingdate<= CURRENT_TIMESTAMP AND (expirationdate > CURRENT_TIMESTAMP OR expirationdate IS NULL)
                AND startdate<= CURRENT_TIMESTAMP AND (stopdate > CURRENT_TIMESTAMP OR stopdate IS NULL)
                 AND (starttime <= 3821 AND endtime >=3821)
                AND idtariffgroup='3'
                AND ( dnidprefix=SUBSTRING('441604293000',1,length(dnidprefix)) OR (dnidprefix='all' AND 0 = (SELECT COUNT(dnidprefix) FROM cc_tariffgroup_plan RIGHT JOIN cc_tariffplan ON cc_tariffgroup_plan.idtariffplan=cc_tariffplan.id WHERE dnidprefix=SUBSTRING('441604293000',1,length(dnidprefix)) AND idtariffgroup=3 ) ))
                AND ( calleridprefix=SUBSTRING('8256092912',1,length(calleridprefix)) OR (calleridprefix='all' AND 0 = (SELECT count(calleridprefix) FROM cc_tariffgroup_plan RIGHT JOIN cc_tariffplan ON cc_tariffgroup_plan.idtariffplan=cc_tariffplan.id WHERE calleridprefix=SUBSTRING('8256092912',1,length(calleridprefix)) AND idtariffgroup=3 )))
                ORDER BY LENGTH(dialprefix) DESC
[13/07/2011 15:41:57]:[file:Class.A2Billing.php - line:1017 - uniqueid:1310568116.64]:[CallerID:8256092912]:[CN:8256092912]:[ERROR ::> RateEngine didnt succeed to match the dialed number over the ratecard (Please check : id the ratecard is well create ; if the removeInter_Prefix is set according to your prefix in the ratecard ; if you hooked the ratecard to the Call Plan)]
[13/07/2011 15:41:57]:[file:a2billing.php - line:572 - uniqueid:1310568116.64]:[CallerID:8256092912]:[CN:8256092912]:[ANSWER fct callingcard_ivr authorize:> -1]

2 – In this example the customer has a zero credit balance. It’s more difficult to find being a little further up the logs and not generating a specific error –

[13/07/2011 16:03:35]:[file:Class.A2Billing.php - line:2807 - uniqueid:1310569415.66]:[CallerID:8256092912]:[CN:8256092912]:[[SET CHANNEL(language) en]]
[13/07/2011 16:03:35]:[file:Class.A2Billing.php - line:2811 - uniqueid:1310569415.66]:[CallerID:8256092912]:[CN:8256092912]:[[credit=0.00000 :: tariff=3 :: status=1 :: isused=0 :: simultaccess=1 :: typepaid=0 :: creditlimit=0 :: language=en]]

3 – In this final example we can see that A2Billing tries to place the call. The first line shows it setting the trunk to ‘inuse+1’. The 2nd line shows it trying to make the call. The 3rd line shows the ‘inuse-1’ meaning it gave up. In this case the trunk name was invalid and didn’t exist in Asterisk. Maybe not straight forward but the debug log gives a good clue as to where the problem lies –

[13/07/2011 16:19:11]:[file:Class.Table.php - line:182 - uniqueid:1310570350.67]:[CallerID:8256092912]:[CN:8256092912]:[Running time=0.00053906440734863 - QUERY=
UPDATE cc_trunk SET inuse=inuse+1 WHERE id_trunk='7'
[13/07/2011 16:19:43]:[file:Class.RateEngine.php - line:1267 - uniqueid:1310570350.67]:[CallerID:8256092912]:[CN:8256092912]:[DIAL SIP/TestTrunk/441604283000,60,HRrL(6000000:61000:30000)]
[13/07/2011 16:19:43]:[file:Class.RateEngine.php - line:1152 - uniqueid:1310570350.67]:[CallerID:8256092912]:[CN:8256092912]:[[TRUNK STATUS UPDATE : UPDATE cc_trunk SET inuse=inuse-1 WHERE id_trunk='7']]

When finished debugging always remember to set ‘logging_level’ back to ‘0’. Leaving it at ‘4’ will really slow the system down with calls flowing through it.

3 thoughts on “A2Billing troubleshooting – verbose logging

  1. matt Post author

    If a2billing isn’t logging when you switch on the debugging then likely something isn’t installed correctly.

  2. Gianfranco

    Hello, I have the a2billing_agi.log emtpy. Can you help me to understand why?

    thank you in advance!

Comments are closed.