[Home]

Summary:ASTERISK-27071: chan_sip: MOH keeps playing on attended transfer to alcatel
Reporter:Jason Tomlinson (Jason)Labels:
Date Opened:2017-06-20 08:58:58Date Closed:
Priority:MajorRegression?
Status:Open/NewComponents:Channels/chan_sip/General
Versions:13.13.0 13.13.1 13.15.0 13.16.0 Frequency of
Occurrence		Constant
Related
Issues:
is duplicated byASTERISK-27676 Attended Transfer Music On Hold
Environment:Centos 7 Alcatel OXEAttachments:( 0) alcatel_trf_problem.txt
( 1) full_sip_trace.txt
( 2) Trace_transfert_Alcatel.pcapng
Description:Since upgrading from asterisk 11 to asterisk 13 (I have tested up to the latest 13.16.0 release), we have a problem with attended transfers to an alcatel pbx in which the call being transferred still has music on hold even after the transfer has completed.
Comments:By: Asterisk Team (asteriskteam) 2017-06-20 08:58:58.937-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Rusty Newton (rnewton) 2017-06-21 18:35:02.238-0500

Being that chan_sip is under extended support now, I'm curious if you can reproduce the issue with chan_pjsip since that is where the core development focus is.

Additionally, if you can provide a packet capture that correlates with a new debug log that would be really helpful in providing further clues into what is going on. If you can do this for chan_sip and chan_pjsip, even better.

Please attach sip endpoint configuration and relevant dialplan as well.
By: Jason Tomlinson (Jason) 2017-06-28 04:57:45.909-0500

In the capture, a call arrives and asterisk dials 1531102
Then, 1531102 dials 1531101
Then 1531102 transfers the incoming call to 1531101
By: Rusty Newton (rnewton) 2017-07-01 10:03:30.072-0500

Thanks for the additional debug. I'm opening this up. Keep in mind that chan_sip is under extended support, which is supported by the broader community and not the core team, so time to resolution may reflect that.

If you find that the issue is reproducible with a core supported module, then please let us know and we'll update the issue.

Thanks,
By: Jason Tomlinson (Jason) 2017-07-27 09:57:57.332-0500

I've been poking around the code to see if I could notice anything.
I dont think it actually has anything to do with alcatel, just the fact that all call legs are from a trunk (I will retest with two asterisk boxes to verify)

We arrive at chan_sip / handle_invite_replaces and it seems nowhere is the music stopped for this channel (compared to asterisk 11 where all channels involved in a transfer are explicitely stopped)

In this function, I added
   struct ast_bridge_channel *other;
   AST_LIST_TRAVERSE(&bridge->channels, other, entry) {
       ast_moh_stop(other->chan); /*attended transfer done, so stop all moh*/
   }

after sending the fake 100 and getting the bridge (so in the "if(bridge)..." block) and this seems to work OK.

Is this a safe thing to do here?
Or should it be an ast_control_unhold frame queued up?
(I assume that it should be chan_sip responsable for unholding channels, so in handle_invite_replaces in this case....)

Thanks



By: Rusty Newton (rnewton) 2017-07-27 14:07:35.288-0500

[~Jason] , the developers don't watch every JIRA issue, usually only ones they are working on directly. If you are looking for advice on source code development or patching then the best place is likely the development chat room. That is located on IRC at #asterisk-dev on irc.freenode.net. If you don't get a response there then you can try the asterisk-dev mailing list at http://lists.digium.com/mailman/listinfo/asterisk-dev

Thanks!
By: Martin Nyström (martin.nystrom) 2018-02-25 14:37:10.318-0600

Perhaps a titel change to this issue is in order. This is NOT occuring on only Alcatel.


This may not appear to be an issue with the Bridge but rather something else. The attended transfer takes place at [2018-02-23 12:12:44].
I've looked through the Events as well. And the Event NewConnectedLine is sent then shortly after MusicOnHoldStart on all channels involved. These events are sent just before the bridge is destroyed.

[2018-02-23 12:10:26] VERBOSE[14021][C-000003ff] netsock2.c: Using SIP RTP CoS mark 5
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] pbx_realtime.c: Executing [0651699650@from-voip-provider:1] NoOp("SIP/siptrunk1.telavox.se-00000759", "Inbound Call")
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] pbx_realtime.c: Executing [0651699650@from-voip-provider:2] Set("SIP/siptrunk1.telavox.se-00000759", "CDR(type)=inbound")
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] pbx_realtime.c: Executing [0651699650@from-voip-provider:3] Set("SIP/siptrunk1.telavox.se-00000759", "CHANNEL(language)=se")
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] pbx_realtime.c: Executing [0651699650@from-voip-provider:4] AGI("SIP/siptrunk1.telavox.se-00000759", "agi://127.0.0.1/square,start_kronans_kundtjanst")
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: START CALLY SQUARE
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: Answer
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: IFTIME 08:00-18:00,mon-fri,*,* true
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: IFTIME *,*,25-26,dec-dec false
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: IFTIME *,*,31-31,dec-dec false
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: IFTIME *,*,1-1,jan-jan false
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: IFTIME *,*,6-6,jan-jan false
[2018-02-23 12:10:26] VERBOSE[15363][C-000003ff] file.c: <SIP/siptrunk1.telavox.se-00000759> Playing '/var/opt/motion2/server/files/sounds/converted/kronans_kundtjanst_Välkommstmedelande_kundservice_val_1_och_2-1505400240447.slin' (language 'se')
[2018-02-23 12:10:55] DTMF[15363][C-000003ff] channel.c: DTMF begin '1' received on SIP/siptrunk1.telavox.se-00000759
[2018-02-23 12:10:55] DTMF[15363][C-000003ff] channel.c: DTMF begin ignored '1' on SIP/siptrunk1.telavox.se-00000759
[2018-02-23 12:10:55] DTMF[15363][C-000003ff] channel.c: DTMF end '1' received on SIP/siptrunk1.telavox.se-00000759, duration 200 ms
[2018-02-23 12:10:55] DTMF[15363][C-000003ff] channel.c: DTMF end passthrough '1' on SIP/siptrunk1.telavox.se-00000759
[2018-02-23 12:10:55] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: no variable selected for the result
[2018-02-23 12:10:55] VERBOSE[15363][C-000003ff] res_agi.c: AGI Script Executing Application: (PLAYBACK) Options: (/var/opt/motion2/server/files/sounds/converted/kronans_kundtjanst_eviexa-1505400244202,)
[2018-02-23 12:10:55] VERBOSE[15363][C-000003ff] file.c: <SIP/siptrunk1.telavox.se-00000759> Playing '/var/opt/motion2/server/files/sounds/converted/kronans_kundtjanst_eviexa-1505400244202.slin' (language 'se')
[2018-02-23 12:11:07] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: Executed command PLAYBACK /var/opt/motion2/server/files/sounds/converted/kronans_kundtjanst_eviexa-1505400244202
[2018-02-23 12:11:07] VERBOSE[15363][C-000003ff] file.c: <SIP/siptrunk1.telavox.se-00000759> Playing '/var/opt/motion2/server/files/sounds/converted/kronans_kundtjanst_1_female-1505400237994.slin' (language 'se')
[2018-02-23 12:11:26] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: no variable selected for the result
[2018-02-23 12:11:26] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: EVAL CONDITION 0>0 false
[2018-02-23 12:11:26] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: sh command: echo Samtalet
[2018-02-23 12:11:26] VERBOSE[15363][C-000003ff] res_agi.c: AGI Script Executing Application: (QUEUE) Options: (Kronans_Kundtjanst,xX,,,3600,,,,,)
[2018-02-23 12:11:26] VERBOSE[15363][C-000003ff] res_musiconhold.c: Started music on hold, class 'queue_music', on channel 'SIP/siptrunk1.telavox.se-00000759'
[2018-02-23 12:11:26] VERBOSE[15363][C-000003ff] res_musiconhold.c: Stopped music on hold on SIP/siptrunk1.telavox.se-00000759
[2018-02-23 12:11:26] VERBOSE[15363][C-000003ff] app_queue.c: Hold time for Kronans_Kundtjanst is 1 minute(s) 0 seconds
[2018-02-23 12:11:26] VERBOSE[15363][C-000003ff] app_queue.c: Told SIP/siptrunk1.telavox.se-00000759 in Kronans_Kundtjanst their queue position (which was 1)
[2018-02-23 12:11:26] VERBOSE[15363][C-000003ff] file.c: <SIP/siptrunk1.telavox.se-00000759> Playing 'queue-thankyou.slin' (language 'se')
[2018-02-23 12:11:27] VERBOSE[15363][C-000003ff] res_musiconhold.c: Started music on hold, class 'queue_music', on channel 'SIP/siptrunk1.telavox.se-00000759'
[2018-02-23 12:11:37] VERBOSE[15363][C-000003ff] netsock2.c: Using SIP RTP CoS mark 5
[2018-02-23 12:11:37] VERBOSE[15363][C-000003ff] app_queue.c: Called SIP/jessica.karlstrom
[2018-02-23 12:11:38] VERBOSE[15363][C-000003ff] app_queue.c: SIP/jessica.karlstrom-00000760 is ringing
[2018-02-23 12:11:39] VERBOSE[15363][C-000003ff] app_queue.c: SIP/jessica.karlstrom-00000760 answered SIP/siptrunk1.telavox.se-00000759
[2018-02-23 12:11:39] VERBOSE[15363][C-000003ff] res_musiconhold.c: Stopped music on hold on SIP/siptrunk1.telavox.se-00000759
[2018-02-23 12:11:39] VERBOSE[15695][C-000003ff] app_mixmonitor.c: Begin MixMonitor Recording SIP/siptrunk1.telavox.se-00000759
[2018-02-23 12:11:39] VERBOSE[15696][C-000003ff] bridge_channel.c: Channel SIP/jessica.karlstrom-00000760 joined 'simple_bridge' basic-bridge <3e33d32a-6796-4f41-a51e-7dec814ee1db>
[2018-02-23 12:11:39] VERBOSE[15363][C-000003ff] bridge_channel.c: Channel SIP/siptrunk1.telavox.se-00000759 joined 'simple_bridge' basic-bridge <3e33d32a-6796-4f41-a51e-7dec814ee1db>
[2018-02-23 12:12:07] VERBOSE[15363][C-000003ff] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/siptrunk1.telavox.se-00000759'
[2018-02-23 12:12:11] VERBOSE[14258][C-00000406] netsock2.c: Using SIP RTP CoS mark 5
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001@from-sip:1] NoOp("SIP/jessica.karlstrom-00000766", "")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001@from-sip:2] Set("SIP/jessica.karlstrom-00000766", "CDR(type)=outbound")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001@from-sip:3] Set("SIP/jessica.karlstrom-00000766", "outboundrouteid=3")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001@from-sip:4] Set("SIP/jessica.karlstrom-00000766", "_XCALLY_MIXMONITOR_UNIQUEID=1519384331.5192")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001@from-sip:5] Set("SIP/jessica.karlstrom-00000766", "_XCALLY_MIXMONITOR_FORMAT=wav")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001@from-sip:6] Set("SIP/jessica.karlstrom-00000766", "DEST=046128001")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001@from-sip:7] Set("SIP/jessica.karlstrom-00000766", "CALLERID(name-pres)=prohib")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001@from-sip:8] Set("SIP/jessica.karlstrom-00000766", "CALLERID(num-pres)=prohib")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001@from-sip:9] Set("SIP/jessica.karlstrom-00000766", "CALLERID(all)=0771612612")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001@from-sip:10] Dial("SIP/jessica.karlstrom-00000766", "SIP/sip.telavox.se/046128001,,xXU(xcally-mixmonitor-context),")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] netsock2.c: Using SIP RTP CoS mark 5
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] app_dial.c: Called SIP/sip.telavox.se/046128001
[2018-02-23 12:12:12] VERBOSE[15827][C-00000406] app_dial.c: SIP/sip.telavox.se-00000767 is ringing
[2018-02-23 12:12:29] VERBOSE[15827][C-00000406] app_dial.c: SIP/sip.telavox.se-00000767 answered SIP/jessica.karlstrom-00000766
[2018-02-23 12:12:29] VERBOSE[15827][C-00000406] app_stack.c: SIP/sip.telavox.se-00000767 Internal Gosub(xcally-mixmonitor-context,s,1) start
[2018-02-23 12:12:29] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [s@xcally-mixmonitor-context:1] NoOp("SIP/sip.telavox.se-00000767", "")
[2018-02-23 12:12:29] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [s@xcally-mixmonitor-context:2] MixMonitor("SIP/sip.telavox.se-00000767", "1519384331.5192.wav,ab")
[2018-02-23 12:12:29] VERBOSE[15848][C-00000406] app_mixmonitor.c: Begin MixMonitor Recording SIP/sip.telavox.se-00000767
[2018-02-23 12:12:29] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [s@xcally-mixmonitor-context:3] Return("SIP/sip.telavox.se-00000767", "")
[2018-02-23 12:12:29] VERBOSE[15827][C-00000406] app_stack.c: Spawn extension (from-voip-provider, , 1) exited non-zero on 'SIP/sip.telavox.se-00000767'
[2018-02-23 12:12:29] VERBOSE[15827][C-00000406] app_stack.c: SIP/sip.telavox.se-00000767 Internal Gosub(xcally-mixmonitor-context,s,1) complete GOSUB_RETVAL=
[2018-02-23 12:12:29] VERBOSE[15849][C-00000406] bridge_channel.c: Channel SIP/sip.telavox.se-00000767 joined 'simple_bridge' basic-bridge <48599f5a-ba75-4f66-9da7-822ab1aad496>
[2018-02-23 12:12:29] VERBOSE[15827][C-00000406] bridge_channel.c: Channel SIP/jessica.karlstrom-00000766 joined 'simple_bridge' basic-bridge <48599f5a-ba75-4f66-9da7-822ab1aad496>
[2018-02-23 12:12:44] VERBOSE[14021][C-000003ff] bridge_channel.c: Channel SIP/sip.telavox.se-00000767 left 'simple_bridge' basic-bridge <48599f5a-ba75-4f66-9da7-822ab1aad496>
[2018-02-23 12:12:44] VERBOSE[15363][C-000003ff] res_musiconhold.c: Stopped music on hold on SIP/siptrunk1.telavox.se-00000759
[2018-02-23 12:12:44] VERBOSE[14021][C-000003ff] bridge_channel.c: Channel SIP/jessica.karlstrom-00000760 left 'simple_bridge' basic-bridge <3e33d32a-6796-4f41-a51e-7dec814ee1db>
[2018-02-23 12:12:44] VERBOSE[14021][C-000003ff] bridge_channel.c: Channel SIP/sip.telavox.se-00000767 swapped with SIP/jessica.karlstrom-00000760 into 'simple_bridge' basic-bridge <3e33d32a-6796-4f41-a51e-7dec814ee1db>
[2018-02-23 12:12:44] VERBOSE[15827][C-00000406] bridge_channel.c: Channel SIP/jessica.karlstrom-00000766 left 'simple_bridge' basic-bridge <48599f5a-ba75-4f66-9da7-822ab1aad496>
[2018-02-23 12:12:44] VERBOSE[15849][C-00000406] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/sip.telavox.se-00000767'
[2018-02-23 12:12:44] VERBOSE[15827][C-00000406] pbx.c: Spawn extension (from-sip, 046-128001, 10) exited non-zero on 'SIP/jessica.karlstrom-00000766'
[2018-02-23 12:12:44] VERBOSE[15363][C-000003ff] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/siptrunk1.telavox.se-00000759'
[2018-02-23 12:12:44] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [h@from-sip:1] NoOp("SIP/jessica.karlstrom-00000766", "")
[2018-02-23 12:12:44] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [h@from-sip:2] Hangup("SIP/jessica.karlstrom-00000766", "")
[2018-02-23 12:12:44] VERBOSE[15827][C-00000406] pbx.c: Spawn extension (from-sip, h, 2) exited non-zero on 'SIP/jessica.karlstrom-00000766'
[2018-02-23 12:13:06] VERBOSE[15849][C-00000406] res_musiconhold.c: Stopped music on hold on SIP/sip.telavox.se-00000767
[2018-02-23 12:13:06] VERBOSE[15849][C-00000406] bridge_channel.c: Channel SIP/sip.telavox.se-00000767 left 'simple_bridge' basic-bridge <3e33d32a-6796-4f41-a51e-7dec814ee1db>
[2018-02-23 12:13:06] VERBOSE[15363][C-000003ff] bridge_channel.c: Channel SIP/siptrunk1.telavox.se-00000759 left 'simple_bridge' basic-bridge <3e33d32a-6796-4f41-a51e-7dec814ee1db>
[2018-02-23 12:13:06] VERBOSE[15363][C-000003ff] res_musiconhold.c: Stopped music on hold on SIP/siptrunk1.telavox.se-00000759
[2018-02-23 12:13:06] VERBOSE[15848][C-00000406] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2018-02-23 12:13:06] VERBOSE[15848][C-00000406] app_mixmonitor.c: End MixMonitor Recording SIP/sip.telavox.se-00000767
[2018-02-23 12:13:06] VERBOSE[15363][C-000003ff] res_agi.c: agi://127.0.0.1/square,start_kronans_kundtjanst: GOTO from-voip-provider 0651699650 5
[2018-02-23 12:13:06] VERBOSE[15363][C-000003ff] res_agi.c: <SIP/siptrunk1.telavox.se-00000759>AGI Script agi://127.0.0.1/square completed, returning 0
[2018-02-23 12:13:06] VERBOSE[15363][C-000003ff] pbx_realtime.c: Executing [0651699650@from-voip-provider:5] hangup("SIP/siptrunk1.telavox.se-00000759", "16")
[2018-02-23 12:13:06] VERBOSE[15363][C-000003ff] pbx.c: Spawn extension (from-voip-provider, 0651699650, 5) exited non-zero on 'SIP/siptrunk1.telavox.se-00000759'
[2018-02-23 12:13:06] VERBOSE[15695][C-000003ff] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2018-02-23 12:13:06] VERBOSE[15695][C-000003ff] app_mixmonitor.c: End MixMonitor Recording SIP/siptrunk1.telavox.se-00000759