[Home]

Summary:ASTERISK-17776: No CDR record is generated if caller hangs up while in Queue and members are busy. Reproduced in 1.8 and 1.6 as well.
Reporter:Attila Megyeri (amegyeri)Labels:
Date Opened:2011-05-02 05:16:24Date Closed:2012-10-29 16:40:00
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Applications/app_queue
Versions:1.8.3 Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:SIP endpoint (SIP/oatest01) is added as member to Queue "oatest" with penalty 1.
Sip endpoint oatest01 is Busy (talking).

A new call is inserted into queue "oatest".

Console says
   -- Got SIP response 486 "Busy Here" back from <Masked IP>
   -- SIP/oademo01-00000043 is busy

Caller hangs up.

No CDR record is  created either in the DB or in the file system.

In other words, NO INFO at all about a missed call...




****** ADDITIONAL INFORMATION ******

Very simple to reproduce.

Create a queue
-----
[oademo]
strategy=rrmemory ;ringall
context=oademo-voicemail
setinterfacevar=yes
setqueuevar=yes
updatecdr=yes
ringinuse=no
joinempty=no
membermacro=oademo-member
----------

Add a member to a queue, with penalty 1
----
queue add member SIP/oademo01 to oademo penalty 1
----


Make the member busy (has a call).
Enqueue a call into the queue:

exten => 223344,1,      NoOp(Queue CDR debug extension)
exten => 223344,n,      Ringing()
exten => 223344,n,      Wait(1)
exten => 223344,n,      Answer()
exten => 223344,n,      Queue(oademo,R,,,240)


Disconnect the call that is waiting in the queue.

Check the CDR - there will be no track of the call.
Comments:By: Attila Megyeri (amegyeri) 2011-05-02 06:18:24

Issue 18689 looks similar, but 19207 can be reproduced 100%.
By: Attila Megyeri (amegyeri) 2011-08-01 03:02:36.451-0500

When can we expect some follow-up, fix or workaround for this issue? This has been pending since 3 months and is quite a major issue.
By: Gregory Hinton Nietsky (irroot) 2011-08-01 05:29:00.834-0500

There is a problem with Queue where it dials but does not like the dial app insert CDR's

here is a bit of work ive done on this
https://reviewboard.asterisk.org/r/1266/

By: Attila Megyeri (amegyeri) 2011-10-01 01:29:42.049-0500

Unfortunately I am not that familiar with the asterisk source so that i could fix the issue myself.

Is there anyone who could assist me with this?
I think this bug is relatively serious and very easy to reproduce.

Any help is greatly appreciated!


By: Attila Megyeri (amegyeri) 2011-10-04 01:11:48.653-0500

Gents - I found a very similar issue that seems to be fixed in eralier versions:

0015122: Abandoned queue calls won't show on CDR

By: Attila Megyeri (amegyeri) 2011-10-04 02:40:35.093-0500

Turned on debug mode, using SVN-branch-1.8-r339147M

Here is a short debug log:

Environment: single member in the queue (oademo01) and is busy (in an outgoing call)
oademo02 calls queue. Call is answered by ast before enqueued.

The debug log shows only from the instant when the caller disconnects the call.

As you see, the only app_queue.c event is, that the call leaved the queue. No notices about hangup, abandon, timeout ,etc.



[Oct  4 09:30:56] DEBUG[4820]: res_rtp_asterisk.c:1099 ast_rtp_raw_write: Difference is 656, ms is 102
[Oct  4 09:30:57] DEBUG[4820]: res_rtp_asterisk.c:1099 ast_rtp_raw_write: Difference is 680, ms is 105
[Oct  4 09:30:57] DEBUG[4820]: res_rtp_asterisk.c:1099 ast_rtp_raw_write: Difference is 664, ms is 103
[Oct  4 09:30:58] DEBUG[4655]: chan_sip.c:7843 find_call: = Looking for  Call ID: ZDY3MzQwNDk4ZDNhYWE5YzhhZTRlMTZkNTgxNTVkZTk. (Checking From) --From tag 402b3759 --To-tag as016f905b
[Oct  4 09:30:58] DEBUG[4655]: chan_sip.c:24499 handle_incoming: **** Received BYE (8) - Command in SIP BYE
[Oct  4 09:30:58] DEBUG[4655]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.15.99.6:5061' into...
[Oct  4 09:30:58] DEBUG[4655]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.15.99.6' and port '5061'.
[Oct  4 09:30:58] DEBUG[4655]: chan_sip.c:3068 sip_alreadygone: Setting SIP_ALREADYGONE on dialog ZDY3MzQwNDk4ZDNhYWE5YzhhZTRlMTZkNTgxNTVkZTk.
[Oct  4 09:30:58] DEBUG[4655]: res_rtp_asterisk.c:2439 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xf4e948'
[Oct  4 09:30:58] DEBUG[4655]: chan_sip.c:23342 handle_request_bye: Received bye, issuing owner hangup
[Oct  4 09:30:58] DEBUG[4655]: chan_sip.c:3326 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.15.99.6:5061
[Oct  4 09:30:58] DEBUG[4820]: channel.c:5145 set_format: Set channel SIP/oademo02-00000008 to write format alaw
[Oct  4 09:30:58] DEBUG[4820]: channel.c:3499 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
###############
[Oct  4 09:30:58] DEBUG[4820]: app_queue.c:2787 leave_queue: Queue 'oademo' Leave, Channel 'SIP/oademo02-00000008'
###############
[Oct  4 09:30:58] DEBUG[4820]: pbx.c:4902 __ast_pbx_run: Spawn extension (oademo-agent,705,4) exited non-zero on 'SIP/oademo02-00000008'
[Oct  4 09:30:58] DEBUG[4820]: channel.c:2679 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/oademo02-00000008'
[Oct  4 09:30:58] DEBUG[4820]: channel.c:2819 ast_hangup: Hanging up channel 'SIP/oademo02-00000008'
[Oct  4 09:30:58] DEBUG[4820]: chan_sip.c:6113 sip_hangup: Hanging up zombie call. Be scared.
[Oct  4 09:30:58] DEBUG[4820]: res_rtp_asterisk.c:2439 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0xf4e948'
[Oct  4 09:30:58] DEBUG[4646]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - oademo02
[Oct  4 09:30:58] DEBUG[4646]: chan_sip.c:25734 sip_devicestate: Checking device state for peer oademo02
[Oct  4 09:30:58] DEBUG[4646]: devicestate.c:458 do_state_change: Changing state for SIP/oademo02 - state 1 (Not in use)
[Oct  4 09:30:58] DEBUG[4646]: devicestate.c:438 devstate_event: device 'SIP/oademo02' state '1'
[Oct  4 09:30:58] DEBUG[4680]: app_queue.c:1493 handle_statechange: Device 'SIP/oademo02' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[Oct  4 09:31:00] DEBUG[4655]: chan_sip.c:7523 sip_alloc: Allocating new SIP dialog for 6679847014ea04ee17d57ac8617f669b@127.0.1.1:0 - OPTIONS (No RTP)
[Oct  4 09:31:00] DEBUG[4655]: acl.c:725 ast_ouraddrfor: For destination '10.15.99.6', our source address is '10.15.99.2'.
[Oct  4 09:31:00] DEBUG[4655]: chan_sip.c:3480 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.15.99.2:5060
[Oct  4 09:31:00] DEBUG[4655]: chan_sip.c:3055 initialize_initreq: Initializing initreq for method OPTIONS - callid 274d7b9d580532af46ec1fd32ac27936@10.15.99.2:5060
[Oct  4 09:31:00] DEBUG[4655]: chan_sip.c:3326 __sip_xmit: Trying to put 'OPTIONS sip' onto UDP socket destined for 10.15.99.6:5060
[Oct  4 09:31:00] DEBUG[4655]: chan_sip.c:7843 find_call: = Looking for  Call ID: 274d7b9d580532af46ec1fd32ac27936@10.15.99.2:5060 (Checking To) --From tag as63d759e7 --To-tag 3a0a0f25
[Oct  4 09:31:00] DEBUG[4655]: chan_sip.c:4012 __sip_ack: Stopping retransmission on '274d7b9d580532af46ec1fd32ac27936@10.15.99.2:5060' of Request 102: Match Found
[Oct  4 09:31:00] DEBUG[4655]: chan_sip.c:5890 sip_destroy: Destroying SIP dialog 274d7b9d580532af46ec1fd32ac27936@10.15.99.2:5060
[Oct  4 09:31:01] DEBUG[4655]: chan_sip.c:7843 find_call: = Looking for  Call ID: YjgwMTRkZTA3MDA2MDU3NTA4NDJmNmQ5ZTBkMGE3M2E. (Checking From) --From tag c4346e38 --To-tag
[Oct  4 09:31:01] DEBUG[4655]: acl.c:725 ast_ouraddrfor: For destination '10.15.99.6', our source address is '10.15.99.2'.
[Oct  4 09:31:01] DEBUG[4655]: chan_sip.c:3480 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.15.99.2:5060
[Oct  4 09:31:01] DEBUG[4655]: chan_sip.c:7523 sip_alloc: Allocating new SIP dialog for YjgwMTRkZTA3MDA2MDU3NTA4NDJmNmQ5ZTBkMGE3M2E. - REGISTER (No RTP)
[Oct  4 09:31:01] DEBUG[4655]: chan_sip.c:24499 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER
[Oct  4 09:31:01] DEBUG[4655]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.15.99.6:5061' into...
[Oct  4 09:31:01] DEBUG[4655]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.15.99.6' and port '5061'.
[Oct  4 09:31:01] DEBUG[4655]: chan_sip.c:3326 __sip_xmit: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.15.99.6:5061
[Oct  4 09:31:02] DEBUG[4655]: chan_sip.c:7843 find_call: = Looking for  Call ID: YjgwMTRkZTA3MDA2MDU3NTA4NDJmNmQ5ZTBkMGE3M2E. (Checking From) --From tag c4346e38 --To-tag
[Oct  4 09:31:02] DEBUG[4655]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.15.99.2:5060' into...
[Oct  4 09:31:02] DEBUG[4655]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.15.99.2' and port '5060'.
[Oct  4 09:31:02] DEBUG[4655]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.15.99.2:5060' into...
[Oct  4 09:31:02] DEBUG[4655]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.15.99.2' and port '5060'.
[Oct  4 09:31:02] DEBUG[4655]: chan_sip.c:24499 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER
[Oct  4 09:31:02] DEBUG[4655]: netsock2.c:134 ast_sockaddr_split_hostport: Splitting '10.15.99.6:5061' into...
[Oct  4 09:31:02] DEBUG[4655]: netsock2.c:188 ast_sockaddr_split_hostport: ...host '10.15.99.6' and port '5061'.
[Oct  4 09:31:02] DEBUG[4655]: db.c:337 ast_db_del: Unable to find key 'oademo02' in family 'SIP/PeerMethods'
[Oct  4 09:31:02] DEBUG[4655]: chan_sip.c:3326 __sip_xmit: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.15.99.6:5061
[Oct  4 09:31:02] DEBUG[4646]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - oademo02
[Oct  4 09:31:02] DEBUG[4646]: chan_sip.c:25734 sip_devicestate: Checking device state for peer oademo02
[Oct  4 09:31:02] DEBUG[4646]: devicestate.c:458 do_state_change: Changing state for SIP/oademo02 - state 5 (Unavailable)
[Oct  4 09:31:02] DEBUG[4646]: devicestate.c:438 devstate_event: device 'SIP/oademo02' state '5'
[Oct  4 09:31:02] DEBUG[4646]: devicestate.c:340 _ast_device_state: No provider found, checking channel drivers for SIP - oademo02
[Oct  4 09:31:02] DEBUG[4646]: chan_sip.c:25734 sip_devicestate: Checking device state for peer oademo02
[Oct  4 09:31:02] DEBUG[4646]: devicestate.c:458 do_state_change: Changing state for SIP/oademo02 - state 5 (Unavailable)
[Oct  4 09:31:02] DEBUG[4646]: devicestate.c:438 devstate_event: device 'SIP/oademo02' state '5'
[Oct  4 09:31:02] DEBUG[4680]: app_queue.c:1493 handle_statechange: Device 'SIP/oademo02' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Oct  4 09:31:02] DEBUG[4680]: app_queue.c:1493 handle_statechange: Device 'SIP/oademo02' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.
[Oct  4 09:31:02] DEBUG[4647]: app_queue.c:1588 extension_state_cb: Extension '802@oademo-hints' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue.

By: Attila Megyeri (amegyeri) 2011-10-06 10:42:40.556-0500

Update: When I set

cdr.conf:

unanswered = yes

I am getting the CDR record, but this is not the right behaviour, as the call is answered before the Queue() command.
This looks exactly the same issue as

0015122: Abandoned queue calls won't show on CDR

Is there anyone following up on this, or I am just wasting time writing the comments here?

Thanks.
By: Jeff Hoppe (jhoppebugs) 2012-02-22 14:14:21.909-0600

This is reproducible in 10.1 as well.    I would like to add that in my sample setup ( a little different than the one specified here) the following:

1. If all "busy" members in the queue have a "paused" status of TRUE, then the CDR will be created.  However, if just one "busy" member has paused status of FALSE then the CDR will not be created. It doesn't matter the pause status at the time of saving the CDR, its the pause status of when the call enters the queue of which I am refering to here.  This is using RealTime queues in my example.

Two work arounds (until this issue is fixed) that I have been using are:
1. Pause the agent when they pick up a call and unpause when they hangup.
2. Reverse engineer a call detail record from the queue_log information.


By: Matt Jordan (mjordan) 2012-07-24 17:42:35.869-0500

So, there's no question that CDR records in Queue are ... interesting.  I won't claim that I can define all of the behavior, since CDR behavior is quirky in general, and there are lots of permutations for how a caller in a queue can end up.

Starting at the beginning: why does the Answer application not write the CDR entry?

Well, the Answer dialplan application is going to do what you think here, it just happens to get nuked later by the Queue application.  While it will Answer the call and set the CDR disposition to "ANSWERED", subsequently, the Queue application is going to mark the CDR record as "NO ANSWER" (or "BUSY", or something indicating failure).  This disposition overwrites the "ANSWERED" disposition that was previously set.

Without the unanswered=yes flag, this record is not written to the CDR.

So what happens with Jeff's pausing of queue members?

The All Paused situation is interesting.  This happens to occur because, when all queue members are paused, no one bothers to update the CDR disposition.  If you have an Answer() before the Queue() application, you'll get a disposition of "ANSWERED", even though all queue members are paused and no one answered the call.  If you don't have an Answer() application call before the Queue() application, you'll get the expected result of "NO ANSWER" (assuming you have unanswered=yes), since no one updated the CDR entry and no one answered the call.

The correct result here should be that if all Queue members are paused - regardless of the presence of the Answer dialplan application - the result is "NO ANSWER" - which again, would not write an entry to the CDR record without the "unanswered=yes" flag.

If at least one queue member is not paused, however, then the Queue application figures out that it did ring someone, and they declined to pick up.  So it decides that the result should be "NO ANSWER" (or "BUSY", as the case may happen to be).  Either way, it does at least bother to update the CDR record with something.

So, there's a bug here, but its more in the inconsistency of what happens with paused queue members.

As Jeff recommended, you're probably better off relying on the queue log, rather then CDRs, to determine what happens with a call in the queue (which is part of the reason why the queue log exists in the first place).
By: Matt Jordan (mjordan) 2012-10-29 15:38:05.245-0500

A patch is going to be committed to Asterisk trunk (which will become version 12) that modifies the behaviour of CDRs to account for some of the situations described in this issue.  We debated doing this in Asterisk 1.8, but in general modifying the behaviour of CDRs in release branches has caused more problems than its solved.

The behaviour in Asterisk 12+ will be:
* If no queue members are paused, the CDR result is whatever the result was prior to going into app_queue.  If the call was answered, this is ANSWERED; otherwise, it is NO ANSWER.
* If some queue members are paused and the caller is never answered, the result is NO ANSWER (prior behaviour: BUSY).
* If all queue members are paused, the CDR result is again whatever the result was prior to going into app_queue.
* If the caller hangs up, times out, or presses '*' with the 'h' option, the result is again not set.

In general, we've kept the modifications as minor as possible and fixed the only truly glaring weirdness, which was that queue members being paused (but not all) caused the disposition to be BUSY.

I don't expect any additional modifications to CDR behaviour to be made, given how difficult it is to get concurrence on CDR behaviour in Queues.  As such, I'm going to close this issue out as "Fixed" - for as much as we can ever "Fix" these kinds of issues.