SERIOUS: Call in queue stuck in DSTCHANNEL, generates multiple levels of CDR variables / BUG?

binntho · June 26, 2018, 8:39am

Hi all

****EDIT: Got the examples mixed up in the first post.

I’ve got a major problem in Asterisk 13:

Occasionally (perhaps 1 out of 10 calls), a call in first place in queue is not answered for quite some time, with other callers being answered
The faulty call genereates multiple entries in CDR table for same call
The final (billable) entry isn’t registered in CDR table.

Example from CLI>queue show:

XXX has 4 calls (max unlimited) in 'ringall' strategy (171s holdtime, 44s talktime), W:1000234, C:227, A:65, SL:0.0% within 0s
   Members:
      SIP/yyyy (ringinuse disabled) (realtime) (Ringing) has taken 59 calls (last was 1378 secs ago)
      SIP/xxxx (ringinuse disabled) (realtime) (in call) (Busy) has taken 168 calls (last was 11 secs ago)
   Callers:
      1. SIP/x.x.x.x-000184ae (wait: 6:36, prio: 0)
      2. SIP/x.x.x.x-000188ab (wait: 1:59, prio: 0)
      3. SIP/x.x.x.x-00018a0f (wait: 0:32, prio: 0)

Shortly afterwards, SIP/xxxx takes the next call, but it’s actually nr. 2 that gets answered. Repeated CLI>queue show:

XXX has 5 calls (max unlimited) in 'ringall' strategy (166s holdtime, 41s talktime), W:1000234, C:228, A:66, SL:0.0% within 0s
   Members:
      SIP/yyyy (ringinuse disabled) (realtime) (Ringing) has taken 59 calls (last was 1483 secs ago)
      SIP/xxxx (ringinuse disabled) (realtime) (in call) (Busy) has taken 169 calls (last was 76 secs ago)
   Callers:
      1. SIP/x.x.x.x-000184ae (wait: 8:21, prio: 0)
      2. SIP/x.x.x.x-00018a0f (wait: 2:17, prio: 0)
      3. SIP/x.x.x.x-00018a10 (wait: 2:15, prio: 0)

Channel SIP/x.x.x.x-000184ae is still in the queue, but channel SIP/x.x.x.x-000188ab (which was in 2nd position) has been answered.

This continued for the next 7-8 minutes, until the sprung-over channel was finally answered.

The sprung over channel, SIP/x.x.x.x-000184ae, is different from the others when using CLI>core show channel command

The “faulty” channel has several levels of CDR variables, with one level being added for each queue timeout period. The other “normal” channels only have one level of CDR variables.

The “faulty” channel has (on all levels) the variable DSTCHANNEL set to SIP/yyyy (which was not taking calls at this time), so it seems to be stuck on calling only one of the two agents in the queue? None of the other channels had DSTCHANNEL set.

Once the call was answered and hungup, I checked the CDR table - there were 51 entries for the call (all with dstchannel = SIP/yyyy) but the billable, answered, call was not in the CDR table.

binntho · June 26, 2018, 8:54am

Note: My first post had an error in the CLI>queue show examples, is corrected now.

david551 · June 26, 2018, 9:08am

You don’t seem to have provided the problem CDRs, or any console logs.

Without them, all I can really point out is that in Asterisk queues, it is the calls that try to find an agent, and they only do so once a second, and not when they are producing things like comfort messages.

binntho · June 26, 2018, 9:58am

Hi David, I didn’t include the CDR variables earlier to avoid cluttering. But here goes:

For a typical channel in queue, using CLI>core show channel

core show channel SIP/x.x.x.x-00018a0f
 -- General --
           Name: SIP/x.x.x.x-00018a0f
           Type: SIP
       UniqueID: 1530000087.192666
       LinkedID: 1530000087.192666
      Caller ID: ccccccccccc
 Caller ID Name: (N/A)
Connected Line ID: (N/A)
Connected Line ID Name: (N/A)
Eff. Connected Line ID: (N/A)
Eff. Connected Line ID Name: (N/A)
    DNID Digits: dddddddd
       Language: da
          State: Up (6)
  NativeFormats: (alaw)
    WriteFormat: slin
     ReadFormat: alaw
 WriteTranscode: Yes (slin@8000)->(alaw@8000)
  ReadTranscode: No
 Time to Hangup: 0
   Elapsed Time: 0h4m59s
      Bridge ID: (Not bridged)
 --   PBX   --
        Context: from-iax
      Extension: dddddddd
       Priority: 2
     Call Group: 0
   Pickup Group: 0
    Application: Queue
           Data: share_40_dkqehodh
 Call Identifer: [C-00003e4a]
      Variables:
cpr=2005581128
PLAYBACKSTATUS=SUCCESS
SIPCALLID=f836a6e2-f3b9-1236-9399-c81f66be4644
SIPDOMAIN=y.y.y.y
SIPURI=sip:mod_sofia@x.x.x.x:5060
  CDR Variables:
level 1: dnid=dddddddd
level 1: clid="" <ccccccccccc>
level 1: src=ccccccccccc
level 1: dst=dddddddd
level 1: dcontext=from-iax
level 1: channel=SIP/x.x.x.x-00018a0f
level 1: lastapp=Queue
level 1: lastdata=share_40_dkqehodh
level 1: start=1530000087.736478
level 1: answer=1530000087.739788
level 1: end=0.000000
level 1: duration=298
level 1: billsec=298
level 1: disposition=1
level 1: amaflags=3
level 1: uniqueid=1530000087.192666
level 1: linkedid=1530000087.192666
level 1: sequence=180046

For the sprung-over channel, CLI>core show channel gives:

core show channel SIP/x.x.x.x-000184ae
 -- General --
           Name: SIP/x.x.x.x-000184ae
           Type: SIP
       UniqueID: 1529999718.190042
       LinkedID: 1529999718.190042
      Caller ID: cccccccccc
 Caller ID Name: (N/A)
Connected Line ID: (N/A)
Connected Line ID Name: (N/A)
Eff. Connected Line ID: (N/A)
Eff. Connected Line ID Name: (N/A)
    DNID Digits: dddddddd
       Language: da
          State: Up (6)
  NativeFormats: (alaw)
    WriteFormat: slin
     ReadFormat: alaw
 WriteTranscode: Yes (slin@8000)->(alaw@8000)
  ReadTranscode: No
 Time to Hangup: 0
   Elapsed Time: 0h9m51s
      Bridge ID: (Not bridged)
 --   PBX   --
        Context: from-iax
      Extension: dddddddd
       Priority: 2
     Call Group: 0
   Pickup Group: 0
    Application: Queue
           Data: share_40_dkqehodh
 Call Identifer: [C-00003da9]
      Variables:
cpr=2301640628
PLAYBACKSTATUS=SUCCESS
SIPCALLID=1c5e43c0-f3b9-1236-9399-c81f66be4644
SIPDOMAIN=y.y.y.y
SIPURI=sip:mod_sofia@x.x.x.x:5060
  CDR Variables:
level 1: dnid=dddddddd
level 1: clid="" <ccccccccccc>
level 1: src=ccccccccccc
level 1: dst=dddddddd
level 1: dcontext=from-iax
level 1: channel=SIP/x.x.x.x-000184ae
level 1: dstchannel=SIP/yyyy-00018683
level 1: lastapp=Queue
level 1: lastdata=share_40_dkqehodh
level 1: start=1529999718.901893
level 1: answer=1529999718.903924
level 1: end=1529999855.529541
level 1: duration=136
level 1: billsec=136
level 1: disposition=0
level 1: amaflags=3
level 1: uniqueid=1529999718.190042
level 1: linkedid=1529999718.190042
level 1: sequence=177546
.
.
.
level 29: dnid=dddddddd
level 29: clid="" <ccccccccccc>
level 29: src=ccccccccccc
level 29: dst=dddddddd
level 29: dcontext=from-iax
level 29: channel=SIP/x.x.x.x-000184ae
level 29: dstchannel=SIP/yyyy-00018e58
level 29: lastapp=Queue
level 29: lastdata=share_40_dkqehodh
level 29: start=1530000301.817231
level 29: answer=1530000301.817231
level 29: end=0.000000
level 29: duration=7
level 29: billsec=7
level 29: disposition=1
level 29: amaflags=3
level 29: uniqueid=1529999718.190042
level 29: linkedid=1529999718.190042
level 29: sequence=182096

And on and on up to level 51, all identical.

binntho · June 26, 2018, 10:17am

Just to explain further: The server uses real-time definitions of queues and SIP phones. On a typical day we have between 200-500 concurrent calls in the morning, split between some 200 queues.

The Asterisk 13 server is a replacement for a much older Asterisk server, but real-time definitions have not been changed except where absolutely necessary due to new demands from Asterisk (e.g. added “uniqeid” column in queue_members table).