[asterisk-bugs] [JIRA] (ASTERISK-27071) chan_sip: MOH keeps playing on attended transfer to alcatel

Sun Feb 25 14:38:24 CST 2018

    [ https://issues.asterisk.org/jira/browse/ASTERISK-27071?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=242380#comment-242380 ] 

Martin Nyström commented on ASTERISK-27071:
-------------------------------------------

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 at 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 at 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 at 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 at 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 at from-sip:1] NoOp("SIP/jessica.karlstrom-00000766", "")
[2018-02-23 12:12:11] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [046-128001 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at from-sip:1] NoOp("SIP/jessica.karlstrom-00000766", "")
[2018-02-23 12:12:44] VERBOSE[15827][C-00000406] pbx_realtime.c: Executing [h at 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 at 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

> chan_sip: MOH keeps playing on attended transfer to alcatel
> -----------------------------------------------------------
>
>                 Key: ASTERISK-27071
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-27071
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Channels/chan_sip/General
>    Affects Versions: 13.13.0, 13.13.1, 13.15.0, 13.16.0
>         Environment: Centos 7
> Alcatel OXE
>            Reporter: Jason Tomlinson
>            Assignee: Unassigned
>         Attachments: alcatel_trf_problem.txt, full_sip_trace.txt, Trace transfert Alcatel.pcapng
>
>
> 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.

--
This message was sent by Atlassian JIRA
(v6.2#6252)