[Home]

Summary:ASTERISK-19183: (Sporadically) missing connectedline event to caller channel in directed pickup app
Reporter:Thomas Arimont (tomaso)Labels:
Date Opened:2012-01-11 03:42:24.000-0600Date Closed:2012-03-29 18:34:19
Priority:MajorRegression?
Status:Closed/CompleteComponents:Applications/app_directed_pickup
Versions:1.8.8.0 Frequency of
Occurrence		Occasional
Related
Issues:
Environment:Attachments:( 0) ASTERISK-19183.patch
( 1) dialplan_around_Pickup.txt
( 2) directed_pickup_trace.txt
( 3) sip_conf.txt
Description:Sporadically the connectedline event to caller (SIP)channel is missing when the directed pickup application is used (custom report). This behaviour seems to be dependent from the load other asterisk threads produce or is dependent from 'internal' timing. In my environment I had to switch on core debug, core verbose, sip debug to replicate the proper behaviour sporadically. Without debugging/tracing I always ran into the 'missing' case.

{noformat}
sip.conf: dumphistory=yes

case o.k.
------
------

---------- SIP HISTORY for '29a1769c5fe7413f15b52ea23176564f@10.54.100.2:5060'
[Jan 10 10:39:04] DEBUG[9869]: chan_sip.c:18183 sip_dump_history:   * SIP Call
[Jan 10 10:39:04] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   001. Masq            Old channel: SIP/1001-0000000d
[Jan 10 10:39:04] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   002. Masq (cont)     ...new owner: SIP/1001-0000000d<MASQ>
[Jan 10 10:39:04] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   003. Cancel          Cause Unknown
[Jan 10 10:39:04] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   004. CancelDestroy
[Jan 10 10:39:04] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   005. Hangup          Got 487 on CANCEL request from us on call without owner. Killin
[Jan 10 10:39:04] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   006. NeedDestroy     Setting needdestroy because received 487 response
[Jan 10 10:39:04] DEBUG[9869]: chan_sip.c:18189 sip_dump_history:
---------- END SIP HISTORY for '29a1769c5fe7413f15b52ea23176564f@10.54.100.2:5060'

---------- SIP HISTORY for '95adeb937527974b'
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18183 sip_dump_history:   * SIP Call
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   001. AuthChal        Auth challenge sent for  - nc 0
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   002. CancelDestroy
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   003. Invite          New call: 95adeb937527974b
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   004. AuthOK          Auth challenge successful for 1680
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   005. ConnectedLine   Called party is now Snom, Test5 <1004>
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   006. ConnectedLine   Called party is now Siemens, Test1 <1001>
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   007. Hangup          Cause Normal Clearing
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   008. AuthResp        Auth response sent for 1680 in realm gemeinschaft.local - nc 1
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   009. NeedDestroy     Setting needdestroy because received 200 response
[Jan 10 10:39:12] DEBUG[9869]: chan_sip.c:18189 sip_dump_history:
---------- END SIP HISTORY for '95adeb937527974b'


case n.o.k.
------------
------------

---------- SIP HISTORY for '5b575f6961c0ecb960c9ac9f436a1e45@10.54.100.2:5060'
[Jan 10 10:37:44] DEBUG[9869]: chan_sip.c:18183 sip_dump_history:   * SIP Call
[Jan 10 10:37:44] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   001. Masq            Old channel: SIP/1001-00000007
[Jan 10 10:37:44] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   002. Masq (cont)     ...new owner: SIP/1001-00000007<MASQ>
[Jan 10 10:37:44] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   003. Cancel          Cause Unknown
[Jan 10 10:37:44] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   004. CancelDestroy
[Jan 10 10:37:44] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   005. Hangup          Got 487 on CANCEL request from us on call without owner. Killin
[Jan 10 10:37:44] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   006. NeedDestroy     Setting needdestroy because received 487 response
[Jan 10 10:37:44] DEBUG[9869]: chan_sip.c:18189 sip_dump_history:
---------- END SIP HISTORY for '5b575f6961c0ecb960c9ac9f436a1e45@10.54.100.2:5060'

---------- SIP HISTORY for '49e6e77076c8e599'
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18183 sip_dump_history:   * SIP Call
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   001. AuthChal        Auth challenge sent for  - nc 0
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   002. CancelDestroy
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   003. Invite          New call: 49e6e77076c8e599
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   004. AuthOK          Auth challenge successful for 1001
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   005. ConnectedLine   Called party is now XXX, XXX <1680>
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   006. Masq            Old channel: SIP/1004-00000006<ZOMBIE>
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   007. Masq (cont)     ...new owner: SIP/1001-00000007
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   008. Hangup          Cause Normal Clearing
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   009. AuthResp        Auth response sent for 1001 in realm gemeinschaft.local - nc 1
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18186 sip_dump_history:   010. NeedDestroy     Setting needdestroy because received 200 response
[Jan 10 10:37:49] DEBUG[9869]: chan_sip.c:18189 sip_dump_history:
---------- END SIP HISTORY for '49e6e77076c8e599'
{noformat}
Comments:By: Matt Jordan (mjordan) 2012-01-11 10:36:32.214-0600

Can you provide the relevant portion of your dialplan surrounding the directed pickup application?  I looked at the DEBUG log you attached, but it'd be helpful to narrow it down where in the dialplan the behavior occurs.
By: Thomas Arimont (tomaso) 2012-01-11 11:01:23.356-0600

Please look at the small attachment with the diaplan code around the Pickup() invoke. I'm not shure if this will really help.
By: Thomas Arimont (tomaso) 2012-01-12 09:23:02.171-0600

By the way, if you look into the sip dumphistory: Somehow the listed order of the dumped vents does not show the real progress. At least single items are mixed ip. This is the case for the events 'CancelDestroy' and 'AuthResp' in the second channel history respectively. Any idea why this has happened?
By: Thomas Arimont (tomaso) 2012-01-13 02:56:22.742-0600

Matt, here comes some more information about how the pickupgroup feature is handled in this spefic dialplan configuration:
- each subscriber can be in (only) one pickup group (system has SIP subscribers only)
- pickupgroup or callgroup conf parameters are not used,
- PICKUPMARK is used instead to implement undirected pickup by using the Pickup() application
- PICKUPMARK channel variable is set to a specific pickup group value (here 00037) everytime a call reaches a pickupgroup member
- an additional call (parallel dial) to a dummy local channel is processed (here with extension *8*00037), this special handling is for manipulating the sip notify contents in the chan_sip.c (maybe you were already wondering about what the *8*00037 => hint,...   is for)
- all pickupgroup member/endpoints of pickup group 00037 have a sip subscription to the extension *8*00037, to get informed by sip notifies (phone popup window)
- the sip endpoint has to dial *8*00037 to pickup a call
- The actual pickup is processed by calling the Pickup(00037@PICKUPMARK) here
By: Thomas Arimont (tomaso) 2012-02-23 08:06:20.150-0600

Matt, is there any progress here?
By: Matt Jordan (mjordan) 2012-02-29 12:40:36.190-0600

I'm sorry Thomas, I had missed where you sent it back to me.

This is currently on the queue to be worked by Mark.  Since he is one of the developers who wrote the Connected Line behavior, it seemed appropriate for him to tackle this issue.
By: Mark Michelson (mmichelson) 2012-03-01 16:07:00.148-0600

Hi Thomas. Do you have progressinband=yes set in sip.conf? I am working on a separate issue where this setting causes some control frames to be dropped if they occur at the same time as the ringback generator fires. If you do have progressinband=yes, then you may be experiencing the same issue, and so the diff from

https://reviewboard.asterisk.org/r/1779

might be relevant to you. If you don't have progressinband=yes, then this is likely not the same issue.
By: Thomas Arimont (tomaso) 2012-03-05 03:37:06.547-0600

The SIP progressinband option is set to 'no' in all cases. Please see enclosed general, default and peer sip settings.
Thomas
By: Mark Michelson (mmichelson) 2012-03-06 12:22:52.783-0600

I started working on this yesterday, and I would like to share what I have found out so far. Consider the following case:

Peer 1: The caller. He is calling Peer 2.
Peer 2: The callee. He is being called by Peer 1.
Peer 3. The one picking up the call. He calls a pickup extension in order to pick up the call from 1 to 2.

Once the call pickup occurs, 1 is connected to 3. 1's display should indicate that he is connected to 3. 3's display should indicate that he is connected to 1.

When I compile with DONT_OPTIMIZE and DEBUG_THREADS, and I turn on verbose messages and SIP debug, the 1's INVITE transaction completes, and then Asterisk sends an UPDATE with 3's information. This is similar to the behavior you see in the "Case O.K." section of the attached debug.

The behavior is different when I compile without DONT_OPTIMIZE and DEBUG_THREADS, but still keep verbose messages and SIP debug enabled. In this case, 3's information is sent to 1 in the 200 OK from Asterisk. There is no UPDATE needed. This seems to imply that the connected line update occurs prior to the completion of the actual call pickup. One thing I have noticed is that if Asterisk thinks that 3 should not be sent connected line updates, then for some reason, Asterisk will not send connected line updates to 1 in this situation.

I am working on trying to figure out why Asterisk behaves this way, and I am trying to determine if there is a more reliable way to structure the call pickup code to ensure that the connected line change properly reaches the caller.
By: Mark Michelson (mmichelson) 2012-03-07 15:40:25.641-0600

I have figured this out.

In the call pickup code, an AST_CONTROL_CONNECTED_LINE frame is queued onto the channel that is doing the pickup. The idea is that this frame can be read either by the bridge code or in app_dial in order to have the update passed on to the calling channel.

I finally noticed what the difference was between our setups. You have the 'I' option specified in your calls to Dial(). This means that if the app_dial code reads the connected line frame, then it will be ignored. However, if the bridging code reads the connected line frame, then the caller gets updated properly.

The way to fix this is to ensure that the connected line update is not processed until the call is bridged.
By: Mark Michelson (mmichelson) 2012-03-07 15:58:45.249-0600

I am attaching ASTERISK-19183.patch. This changes the connected line update to be queued after the answer. This fixed the problem on my system. Let me know if it fixes your problem.
By: Thomas Arimont (tomaso) 2012-03-07 23:11:02.275-0600

Mark,
this sounds more than reasonable. I will test this a.s.a.p and let you know about the results.
Thanks!
Thomas
By: Maurice Winkels (maurice) 2012-03-21 04:17:20.786-0500

Hi Mark,
sorry, my actual JIRA account is blocked now for more than one week, so I couldn't answer.
Now I'll try it with this private JIRA account.
Your patch seems to solve the problem. I couldn't reproduce this issue any longer.
Thanks, good job!

Regards
Thomas
By: Thomas Arimont (tomaso) 2012-03-22 09:12:01.534-0500

I think we can close this issue.