Cgrates continues debit balance on unsuccessful calls (Asterisk agent)

[Evgeniy Bozhet]

Hello!

I'm faced strange behavior, not seen before.

Cgrates 0.10 with Astersik agent.

On some count of unsuccessful calls (NO ANSWER dispo on Asterisk) I got error on cgrates log:

Aug 24 16:39:03 ovpprodbilling CGRateS <CGRFreevoipBilling> [3721]: <StatQueue> metricID: *tcc, add eventID: dd3f16d, error: NOT_FOUND:Cost
Aug 24 16:39:03 ovpprodbilling CGRateS <CGRFreevoipBilling> [3721]: <StatS> Queue: freevoip.org:Stats2, ignoring event: freevoip.org:dd3f16d, error: NOT_FOUND:Cost
Aug 24 16:39:03 ovpprodbilling CGRateS <CGRFreevoipBilling> [3721]: <CDRs> error: <PARTIALLY_EXECUTED> processing event &{CGREvent:0xc000e76c48 ArgDispatcher:<nil>} with Stats
Aug 24 16:39:03 ovpprodbilling CGRateS <CGRFreevoipBilling> [3721]: <SessionS> error <PARTIALLY_EXECUTED> posting CDR with CGRID: <c9466bf1e210206a8558d7a9ef443eb209aa45e9>
Aug 24 16:39:04 ovpprodbilling CGRateS <CGRFreevoipBilling> [3721]: <AsteriskAgent> Error: PARTIALLY_EXECUTED when attempting to process CDR for channelID: 1598276342.1481

After this account balance continues debit until cgrates restart (even call was already disconnected and cdr finalized hours ago). Ngrep shows repeating sequence as follow:

T 127.0.0.1:34002 -> 127.0.0.1:2012 [AP] #459
  {"method":"Responder.MaxDebit","params":[{"Category":"call","Tenant":"freevoip.org","Subject":"1000055","Account":"1000053","Destination":"00179527955838","TimeStart":"202
  0-08-24T19:51:22.934+03:00","TimeEnd":"2020-08-24T19:51:27.934+03:00","LoopIndex":2308,"DurationIndex":11545000000000,"FallbackSubject":"","RatingInfos":null,"Increments":
  null,"ToR":"","ExtraFields":null,"MaxRate":0,"MaxRateUnit":0,"MaxCostSoFar":15.348200000000322,"CgrID":"c9466bf1e210206a8558d7a9ef443eb209aa45e9","RunID":"*default","Force
  Duration":false,"PerformRounding":false,"DryRun":false,"DenyNegativeAccount":false}],"id":57862}.                                                                          
#
T 127.0.0.1:34002 -> 127.0.0.1:2012 [AP] #460
  {"method":"ThresholdSv1.ProcessEvent","params":[{"ThresholdIDs":null,"Tenant":"freevoip.org","ID":"5f101327-63ef-4fb0-ae5d-9803dff45114","Time":null,"Event":{"Account":"10
  00053","BalanceID":"BAL_1000053","EventSource":"AccountS","EventType":"BalanceUpdate","Units":868.94855}}],"id":57863}.                                                    
##
T 127.0.0.1:2012 -> 127.0.0.1:34002 [AP] #462
  {"id":57863,"result":null,"error":"NOT_FOUND"}.                                                                                                                            
#
T 127.0.0.1:2012 -> 127.0.0.1:34002 [AP] #463
  {"id":57862,"result":{"Category":"call","Tenant":"freevoip.org","Subject":"1000055","Account":"1000053","Destination":"00179527955838","ToR":"*voice","Cost":0.00665,"Times
  pans":[{"TimeStart":"2020-08-24T19:51:22.934+03:00","TimeEnd":"2020-08-24T19:51:27.934+03:00","Cost":0.00665,"RateInterval":{"Timing":{"Years":[],"Months":[],"MonthDays":[
  ],"WeekDays":[],"StartTime":"00:00:00","EndTime":""},"Rating":{"ConnectFee":0,"RoundingMethod":"*up","RoundingDecimals":3,"MaxCost":0,"MaxCostStrategy":"","Rates":[{"Group
  IntervalStart":0,"Value":0.08,"RateIncrement":1000000000,"RateUnit":60000000000}]},"Weight":10},"DurationIndex":11545000000000,"Increments":[{"Duration":1000000000,"Cost":
  0.00133,"BalanceInfo":{"Unit":null,"Monetary":{"UUID":"a0ae728a-657c-4daa-bd5a-880e8a255b2b","ID":"BAL_1000053","Value":868.94855,"RateInterval":null},"AccountID":"freevoi
  p.org:1000053"},"CompressFactor":5}],"RoundIncrement":null,"MatchedSubject":"*out:freevoip.org:call:*any","MatchedPrefix":"001795279","MatchedDestId":"DST_P001795279","Rat
  ingPlanId":"RP_INTERNAL_OUT_COMMON","CompressFactor":1}],"RatedUsage":5000000000,"AccountSummary":{"Tenant":"freevoip.org","ID":"1000053","BalanceSummaries":[{"UUID":"a0ae
  728a-657c-4daa-bd5a-880e8a255b2b","ID":"BAL_1000053","Type":"*monetary","Value":868.94855,"Disabled":false}],"AllowNegative":false,"Disabled":false}},"error":null}.      
##

SIP accounts have shared balances (through substitution balance ID in attributes).

Asterisk dialplan routine responsible for auth on cgrates:

[sub-cgr-auth]
exten => _X.,1,Verbose("CGR Auth routine entered...")
    same => n,Verbose("Routine entered with parameters ${ARG1} ${ARG2} ${ARG3}")
    same => n,Set(CGRMaxSessionTime=0); use it to disconnect automatically the call if CGRateS is not active
    same => n,Set(CALLERID(num)=${ARG2})
    same => n,DumpChan()
    same => n,Stasis(cgrates_auth,AccountParent=${ARG1},AccountOriginate=${ARG2},OriginCallID=${ARG3},OriginFromTag=${ARG4},OriginCallerID=${ARG5},"cgr_reqtype=*prepaid","cgr_flags=*accounts,*attributes,*stats,*thresholds")
    same => n,Return()

Asterisk on chan_sip, not chan_pjsip and can it be a culprit too?

Cgrates deployed on dedicated server and connected to ARI remotely (ping between servers ~3 ms).

Thank you for any help!

[Evgeniy Bozhet]

I also can confirm that on v0.10.1 this behavior is 100% reproducible on my setup.

Everything I need is broke somehow outbound trunk on Asterisk box (start getting "Circuit/channel congestion" for every call for example) and spam PBX with some count (5 - 10) of new simultaneous calls to same destination. After that I see loop with ("method":"Responder.MaxDebit").

Also active_sessions in console returns no result so it is not directly stuck sessions issue. On Asterisk box no stuck calls too at that time.

Any help on this will be appreciated.

[Teofil Voivozeanu]

Hi Evgeniy,

We suspect that this is related to the issue that we investigating right now.

For updates please follow it on GitHub (https://github.com/cgrates/cgrates/issues/2354 ).

Thanks,

TeoV

[Evgeniy Bozhet]

Thank you!

пʼятниця, 28 серпня 2020 р. 14:39:25 UTC+3 користувач Teofil Voivozeanu написав: